[question] - [DEBUG] messages from the ccloud-sdk ?

[FabioBatSilva]

I understand this might not be a issue with the confluent terraform provider
But i'm trying to track down this issue : pulumi/pulumi-confluentcloud#48 and it has led me here.

It seems like the terraform provider is flooding the logs with [DEBUG] messages from the ccloud-sdk.

2024/03/18 16:17:59 [DEBUG] POST https://xxx.confluent.cloud/compatibility/subjects/chesscom.xxx-value/versions?verbose=true
2024/03/18 16:18:00 [DEBUG] POST https://xxx.confluent.cloud/subjects/chesscom.xxx-value?normalize=false

Is this something confluent terraform provider is configured to do ?
Can someone please point me to where the log level for the sdk is defined ?

Thanks

[linouk23]

@FabioBatSilva thanks for creating the issue!

Here are 2 code pointers that might be helpful:

• https://github.com/confluentinc/terraform-provider-confluent/blob/master/internal/provider/provider.go#L448
• https://github.com/confluentinc/ccloud-sdk-go-v2/blob/master/apikeys/v2/configuration.go#L120

[FabioBatSilva]

Thanks @linouk23, that was very helpfull.

I believe i found the log entries tha are causing problem.

When running 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 tf_req_id=674347de-096d-5287-519d-d7afc4fbcb45 tf_rpc=ReadResource @caller=/terraform/terraform-provider-confluent/internal/provider/resource_schema.go:805 @module=provider tf_resource_type=confluent_schema timestamp=2024-03-18T19:30:33.970-0400
2024-03-18T19:30:33.970-0400 [DEBUG] provider.terraform-provider-confluent: Finished reading Schema "xxxx-xxxxx/chesscom/xxxx.proto/latest": tf_req_id=674347de-096d-5287-519d-d7afc4fbcb45 tf_rpc=ReadResource @caller=/terraform/terraform-provider-confluent/internal/provider/resource_schema.go:629 @module=provider schema_id=xxxx-xxxxx/chesscom/xxxx.proto/latest tf_provider_addr=provider tf_resource_type=confluent_schema timestamp=2024-03-18T19:30:33.970-0400

It seems like the http call logs get double formatted for some reason.

{time} [DEBUG] provider.terraform-provider-confluent: {time} [DEBUG] {message}

I guess that might be causing issues with the pulumi bridge:
https://github.com/pulumi/pulumi-terraform-bridge/blob/0d7f807c7e1e97bca265307d03f8fc524428c52f/pkg/tfbridge/log.go#L91-L98

I'll post my finding on the pulumi side, but perhaps we can also clean that up here..

Any idea where that message is getting formatted ?

[linouk23]

Thanks for investigating it @FabioBatSilva!

I'm not sure whether it helps but

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 tf_req_id=674347de-096d-5287-519d-d7afc4fbcb45 tf_rpc=ReadResource @caller=/terraform/terraform-provider-confluent/internal/provider/resource_schema.go:805 @module=provider tf_resource_type=confluent_schema timestamp=2024-03-18T19:30:33.970-0400
2024-03-18T19:30:33.970-0400 [DEBUG] provider.terraform-provider-confluent: Finished reading Schema "xxxx-xxxxx/chesscom/xxxx.proto/latest": tf_req_id=674347de-096d-5287-519d-d7afc4fbcb45 tf_rpc=ReadResource @caller=/terraform/terraform-provider-confluent/internal/provider/resource_schema.go:629 @module=provider schema_id=xxxx-xxxxx/chesscom/xxxx.proto/latest tf_provider_addr=provider tf_resource_type=confluent_schema timestamp=2024-03-18T19:30:33.970-0400

are coming from TF Provider logs directly:

tflog.Debug(ctx, fmt.Sprintf("Fetched Schemas %q: %s", d.Id(), schemasJson), map[string]interface{}{schemaLoggingKey: d.Id()})

whereas

logs like

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

are coming from the SDK.

It also seems like all of

{time} [DEBUG] provider.terraform-provider-confluent: {time} [DEBUG] {message}

correspond to SDK logs.

[FabioBatSilva]

Thanks..

Just got some pointers here
pulumi/pulumi-confluentcloud#48 (comment)

The theory is that retryablehttp client seems to be using i'ts own logger

terraform-provider-confluent/internal/provider/factory_utils.go

Line 140 in d6298f5

retryClient := retryablehttp.NewClient()

https://github.com/hashicorp/go-retryablehttp/blob/main/client.go#L609-L616

I think there might also be an issue with the way pulumi parses the logs
but perhaps we can adjust things here?

Will try to test that out tomorow.