eksctl aws logging includes bizarre (MISSING) replacements

[mdaniel]

What happened?

Running with --verbose 5 emits messages containing an unbelievable number of %!!(MISSING) lines

What you expected to happen?

The payloads should be logged as they actually are

How to reproduce it?

eksctl create cluster --verbose 5 --config-file $foo or eksctl get nodegroups --cluster $c --verbose 5 -- basically any non-trivial interaction with AWS

Anything else we need to know?

• macOS 10.14.5
• compiled (I experienced this with 0.1.33 and with fd7ee50)
• the normal ~/.aws/credentials although with an MFA

Versions
Please paste in the output of these commands:

$ eksctl version
[ℹ]  version.Info{BuiltAt:"1559689936", GitCommit:"0.1.33-17-gfd7ee501", GitTag:""}
$ uname -a
Darwin mdaniel.local 18.6.0 Darwin Kernel Version 18.6.0: Thu Apr 25 23:16:27 PDT 2019; root:xnu-4903.261.4~2/RELEASE_X86_64 x86_64
$ kubectl version
Client Version: version.Info{Major:"1", Minor:"14", GitVersion:"v1.14.2", GitCommit:"66049e3b21efe110454d67df4fa62b08ea79a19b", GitTreeState:"clean", BuildDate:"2019-05-21T23:03:55Z", GoVersion:"go1.12.5", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"12+", GitVersion:"v1.12.6-eks-d69f1b", GitCommit:"d69f1bf3669bf00b7f4a758e978e0e7a1e3a68f7", GitTreeState:"clean", BuildDate:"2019-02-28T20:26:10Z", GoVersion:"go1.10.8", Compiler:"gc", Platform:"linux/amd64"}

Logs

Action=CreateStack&Capabilities.member.1=CAPABILITY_IAM&StackName=eksctl-eks-prod-nodegroup-p2-xl&Tags.member.1.Key=alpha.eksctl.io%!!(MISSING)F(MISSING)cluster-name&Tags.member.1.Value=eks-prod&Tags.member.2.Key=eksctl.cluster.k8s.io%!!(MISSING)F(MISSING)v1alpha1%!!(MISSING)F(MISSING)cluster-name&Tags.member.2.Value=eks-prod&Tags.member.3.Key=eksctl.io%!!(MISSING)F(MISSING)v1alpha2%!!(MISSING)F(MISSING)nodegroup-name&Tags.member.3.Value=p2-xl&Tags.member.4.Key=project&Tags.member.4.Value=k8s&Tags.member.5.Key=alpha.eksctl.io%!!(MISSING)F(MISSING)nodegroup-name&Tags.member.5.Value=p2-xl&TemplateBody=%!!(MISSING)B(MISSING)%!!(MISSING)A(MISSING)WSTemplateFormatVersion%!A(MISSING)%!!(MISSING)-(MISSING)09-09%!C(MISSING)%!!(MISSING)D(MISSING)escription%!A(MISSING)%!!(MISSING)E(MISSING)KS+nodes+%!!(MISSING)A(MISSING)MI+family%!!(MISSING)A(MISSING)+AmazonLinux2%!!(MISSING)C(MISSING)+SSH+access%!!(MISSING)A(MISSING)+true%!!(MISSING)C(MISSING)+private+networking%!!(MISSING)A(MISSING)+true%!!(MISSING)+(MISSING)%!!(MISSING)B(MISSING)created+and+managed+by+eksctl%!!(MISSING)D(MISSING)%!C(MISSING)%!!(MISSING)R(MISSING)esources%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)E(MISSING)gressInterCluster%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)T(MISSING)ype%!A(MISSING)%!!(MISSING)A(MISSING)WS%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)EC2%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)SecurityGroupEgress%!C(MISSING)%!!(MISSING)P(MISSING)roperties%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)D(MISSING)escription%!A(MISSING)%!!(MISSING)A(MISSING)llow+control+plane+to+communicate+with+worker+nodes+in+group+p2-xl+%!!(MISSING)k(MISSING)ubelet+and+workload+TCP+ports%!C(MISSING)%!!(MISSING)D(MISSING)estinationSecurityGroupId%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)R(MISSING)ef%!A(MISSING)%!!(MISSING)S(MISSING)G%!D(MISSING)%!!(MISSING)C(MISSING)%!!(MISSING)F(MISSING)romPort%!A(MISSING)1025%!!(MISSING)C(MISSING)%!!(MISSING)G(MISSING)roupId%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)F(MISSING)n%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)ImportValue%!A(MISSING)%!!(MISSING)e(MISSING)ksctl-eks-prod-cluster%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)SecurityGroup%!D(MISSING)%!!(MISSING)C(MISSING)%!!(MISSING)I(MISSING)pProtocol%!A(MISSING)%!!(MISSING)t(MISSING)cp%!C(MISSING)%!!(MISSING)T(MISSING)oPort%!A(MISSING)65535%!!(MISSING)D(MISSING)%!!(MISSING)D(MISSING)%!!(MISSING)C(MISSING)%!!(MISSING)E(MISSING)gressInterClusterAPI%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)T(MISSING)ype%!A(MISSING)%!!(MISSING)A(MISSING)WS%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)EC2%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)SecurityGroupEgress%!C(MISSING)%!!(MISSING)P(MISSING)roperties%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)D(MISSING)escription%!A(MISSING)%!!(MISSING)A(MISSING)llow+control+plane+to+communicate+with+worker+nodes+in+group+p2-xl+%!!(MISSING)w(MISSING)orkloads+using+HTTPS+port%!!(MISSING)C(MISSING)+commonly+used+with+extension+API+servers%!C(MISSING)%!!(MISSING)D(MISSING)estinationSecurityGroupId%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)R(MISSING)ef%!A(MISSING)%!!(MISSING)S(MISSING)G%!D(MISSING)%!!(MISSING)C(MISSING)%!!(MISSING)F(MISSING)romPort%!A(MISSING)443%!!(MISSING)C(MISSING)%!!(MISSING)G(MISSING)roupId%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)F(MISSING)n%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)ImportValue%!A(MISSING)%!!(MISSING)e(MISSING)ksctl-eks-prod-cluster%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)SecurityGroup%!D(MISSING)%!!(MISSING)C(MISSING)%!!(MISSING)I(MISSING)pProtocol%!A(MISSING)%!!(MISSING)t(MISSING)cp%!C(MISSING)%!!(MISSING)T(MISSING)oPort%!A(MISSING)443%!!(MISSING)D(MISSING)%!!(MISSING)D(MISSING)%!!(MISSING)C(MISSING)%!!(MISSING)I(MISSING)ngressInterCluster%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)T(MISSING)ype%!A(MISSING)%!!(MISSING)A(MISSING)WS%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)EC2%!!(MISSING)A(MISSING)%!!(MISSING)A(MISSING)SecurityGroupIngress%!C(MISSING)%!!(MISSING)P(MISSING)roperties%!A(MISSING)%!!(MISSING)B(MISSING)%!!(MISSING)D(MISSING)escription%!A(MISSING)%!!(MISSING)A(MISSING)llow+worker+nodes+in+group+p2-xl+to+communicate+with+control+plane+%!!(MISSING)k(MISSING)ubelet+and+workload+TCP+ports%!C(MISSING)
and that goes on for pages and pages

[errordeveloper]

This is a know issue in AWS Go library.

[errordeveloper]

If someone can check if there is an upstream issue, please post it here and then we can close. Also would be good to check if the v2 client has this same bug or not.

[mdaniel]

I tried to find any such issue in their issues by searching for log "MISSING", logging "MISSING", logging format, and some other permutations without success. A cursory web search didn't materialize anything, either (obligatory Google)

Does AWS use something other than GH issues for issue tracking?

As for the v2 question, I'd bet it suffers from the same problem; is the fix for this problem just changing that line from .Println(args...) to .Println("%s", args...)?

[errordeveloper]

I found aws/aws-sdk-go#894 (comment) and realised that this is purely to do with %s in the URL, which confuses printf.

[mdaniel]

I can confirm this is not an AWS SDK issue

If one takes the newSession body and replaces the logger.Debug() with fmt.Printf("%s", fmt.Sprintln(args...)) then the (MISSING) silliness goes away. As one might suspect, eksctl then also behaves sanely by removing the custom aws.LoggerFunc, too, which is why I'm able to state that it is not an AWS SDK issue

I can trivially reproduce this problem:

package main

import (
	"github.com/kris-nova/logger"
)

func main() {
	// :point_down: as one would receive from the `fmt.Sprintln(args...)`
	s := "Action=DescribeStacks&StackName=arn%3Aaws%3Acloudformation%3Aus-west-2%3A"
	logger.Level = 1000
	logger.Debug(s)
	logger.Debug("%s", s)
}

cheerfully produces:

2019-06-05T15:30:12-07:00 [▶]  Action=DescribeStacks&StackName=arn%!!(MISSING)A(MISSING)aws%!!(MISSING)A(MISSING)cloudformation%!!(MISSING)A(MISSING)us-west-2%!!(MISSING)A(MISSING)
2019-06-05T15:30:12-07:00 [▶]  Action=DescribeStacks&StackName=arn%!A(MISSING)aws%!A(MISSING)cloudformation%!A(MISSING)us-west-2%!A(MISSING)

So the first style, which is erroneously being used by eksctl, expects a format as its first argument, so I can actually forgive the logger library for doing weird stuff in that circumstance because PEBKAC; but I don't have a good explanation why correctly using a "%s" format string still produces double formatting

Anyway, the bug in "github.com/kris-nova/logger" aside, this issue is happening because eksctl is attempting to supersede the normal AWS SDK logging behavior in order to add colors and unicode characters.

Please do consider reopening this issue, as it is real and it is localized to eksctl

[errordeveloper]

Thanks for looking into it, I didn't realise this was due to our custom logger. By the way it's not about colour and unicode, it's just so we have consistent log format. We may need to rework logging, by the way, because we should make functionality accessible as a library (see #813), hence will need to let library consumers to swap out our logger.

[sayboras]

@mdaniel thanks for your detailed analysis, I have raised two PRs (one in upstream and one in eksctl) to address this issue #2084 and krisnova/logger#4

[michaelbeaumont]

Duplicate of #2237

[perholmes]

In case someone wastes a day on this issue, the problem is printing URLs using the formatting string. Using "%s", url, with the URL as the argument is just fine.