Open FabioBatSilva opened 3 months ago
@FabioBatSilva thanks for creating the issue!
Here are 2 code pointers that might be helpful:
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 ?
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.
Thanks..
Just got some pointers here https://github.com/pulumi/pulumi-confluentcloud/issues/48#issuecomment-2005372312
The theory is that retryablehttp client seems to be using i'ts own logger https://github.com/confluentinc/terraform-provider-confluent/blob/d6298f5c7de36e1b5dd9d53b7d1cc638269e6476/internal/provider/factory_utils.go#L140 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.
I understand this might not be a issue with the confluent terraform provider But i'm trying to track down this issue : https://github.com/pulumi/pulumi-confluentcloud/issues/48 and it has led me here.
It seems like the terraform provider is flooding the logs with
[DEBUG]
messages from the ccloud-sdk.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