Provider spits out [DEBUG] messages in logs

[jkodroff]

What happened?

In v1.5.0 of the provider, spinning up resources creates debug log output:

Diagnostics:
  pulumi:pulumi:Stack (workshop-confluent-dev):
    2022/11/22 15:33:33 [DEBUG] POST https://api.confluent.cloud/org/v2/environments
    2022/11/22 15:33:33 [DEBUG] GET https://api.confluent.cloud/org/v2/environments/env-xqprvk
    2022/11/22 15:33:34 [DEBUG] POST https://api.confluent.cloud/cmk/v2/clusters
    2022/11/22 15:33:40 [DEBUG] GET https://api.confluent.cloud/cmk/v2/clusters/lkc-j3ojrq?environment=env-xqprvk
    2022/11/22 15:33:40 [DEBUG] GET https://api.confluent.cloud/cmk/v2/clusters/lkc-j3ojrq?environment=env-xqprvk

Steps to reproduce

n/a

Expected Behavior

n/a

Actual Behavior

n/a

Output of pulumi about

No response

Additional context

No response

Contributing

Vote on this issue by adding a 👍 reaction.
To contribute a fix for this issue, leave a comment (and link to your pull request, if you've opened one already).

[AaronFriel]

@jkodroff could you drop a github repro or gist with a program creating resources to repro?

[jkodroff]

https://github.com/pulumi/workshops/tree/main/confluent

[ebertn]

This is happening with us as well 👍. Would love it if this became optional, as it is occasionally useful for debugging.

[FabioBatSilva]

We have hundreds of topics/schema in terraform currently and trying migrate into Pulumi,
The amount of noise this generates makes the pulumi output unusable..

Can someone please help describe what needs to happen here ?
If no one is looking into it i'm happy to give it a try.

[praneetloke]

@FabioBatSilva the debug messages appear to be from the upstream provider's use of go-retryablehttp. Specifically, if you look at https://github.com/hashicorp/go-retryablehttp/blob/main/client.go#L609-L616 in that library, it seems to use the default logger instance which logs via stderr. So yeah the upstream provider either needs to provides its own logger or should set it to nil when constructing an instance of the HTTP client from go-retryablehttp.

[FabioBatSilva]

Thanks @praneetloke.

I was able to get some log entries on the tf provider.

When running terraform with debug enabled i get :

2024-03-18T19:30:33.710-0400 [DEBUG] provider.terraform-provider-confluent: Reading Schema "xxxx-xxxxx/chesscom/xxxx.proto/latest": @module=provider tf_req_id=674347de-096d-5287-519d-d7afc4fbcb45 tf_resource_type=confluent_schema tf_rpc=ReadResource @caller=/terraform/terraform-provider-confluent/internal/provider/resource_schema.go:597 schema_id=xxxx-xxxxx/chesscom/xxxx.proto/latest tf_provider_addr=provider timestamp=2024-03-18T19:30:33.710-0400
2024-03-18T19:30:33.710-0400 [DEBUG] provider.terraform-provider-confluent: 2024/03/18 19:30:33 [DEBUG] GET https://xxxx.gcp.confluent.cloud/subjects/chesscom%2Fxxxx.proto/versions/latest
2024-03-18T19:30:33.941-0400 [DEBUG] provider.terraform-provider-confluent: 2024/03/18 19:30:33 [DEBUG] GET https://xxxx.gcp.confluent.cloud/schemas?subjectPrefix=chesscom%2Fxxxx.proto
2024-03-18T19:30:33.970-0400 [DEBUG] provider.terraform-provider-confluent: Fetched Schemas "xxxx-xxxxx/chesscom/xxxx.proto/latest": [...]: @caller=/terraform/terraform-provider-confluent/internal/provider/resource_schema.go:781 @module=provider schema_id=xxxx-xxxxx/chesscom/xxxx.proto/latest tf_resource_type=confluent_schema tf_rpc=ReadResource tf_provider_addr=provider tf_req_id=674347de-096d-5287-519d-d7afc4fbcb45 timestamp=2024-03-18T19:30:33.970-0400
2024-03-18T19:30:33.970-0400 [DEBUG] provider.terraform-provider-confluent: Fetched Schema "xxxx-xxxxx/chesscom/xxxx.proto/latest": {...}: schema_id=xxxx-xxxxx/chesscom/xxxx.proto/latest tf_provider_addr=provider 

Is the parsing here breaking the on pulumi side bc of the double [DEBUG] ?

[praneetloke]

@FabioBatSilva Ah I wasn't aware of that part in the bridge repo honestly.

Is the parsing here breaking the on pulumi side bc of the double [DEBUG] ?

Maybe this line since there are two ]s: https://github.com/pulumi/pulumi-terraform-bridge/blob/master/pkg/tfbridge/log.go#L94, so the end index of ] would be incorrect and therefore the extracted substring would be incorrect and not match any of the expected prefixes. (This wouldn't be the case since IndexRune returns the first match.) You could try to reproduce that with a test in log_test.go and maybe propose a fix.

EDIT: Note that the double [DEBUG] situation is only when you enable the TF debug mode. Under normal conditions, that's not the case. So maybe the log redirector is seeing it as [INFO] [DEBUG] and is therefore routing the debug message from go-retryablehttp as though it were an info message. I still think your best bet is to make a fix in the upstream provider at the location I linked in my previous comment.

[FabioBatSilva]

I tried to reproduce the issue with log_test but it seems ok, Maybe that is happening somewhere else..

I'v opened a PR to provide a logger for retryablehttp
confluentinc/terraform-provider-confluent#374