Add some debug logs (#28)

Add some debug logs

COVERAGE

@@ -1 +1 @@
-65.47
+68.71

cmd/run.go

@@ -1,6 +1,8 @@
 package cmd
 
 import (
+	"context"
+
 	"github.com/aws/aws-sdk-go/aws"
 	"github.com/aws/aws-sdk-go/aws/credentials"
 	"github.com/aws/aws-sdk-go/aws/credentials/stscreds"
@@ -11,6 +13,7 @@ import (
 	"github.com/chanzuckerberg/blessclient/pkg/util"
 	kmsauth "github.com/chanzuckerberg/go-kmsauth"
 	cziAWS "github.com/chanzuckerberg/go-misc/aws"
+	"github.com/davecgh/go-spew/spew"
 	multierror "github.com/hashicorp/go-multierror"
 	homedir "github.com/mitchellh/go-homedir"
 	"github.com/pkg/errors"
@@ -29,6 +32,8 @@ var runCmd = &cobra.Command{
 	SilenceErrors: true,
 	RunE: func(cmd *cobra.Command, args []string) error {
 		log.Debugf("Running blessclient v%s", util.VersionCacheKey())
+		ctx := context.Background()
+
 		configFile, err := cmd.Flags().GetString("config")
 		if err != nil {
 			return errs.ErrMissingConfig
@@ -37,11 +42,13 @@ var runCmd = &cobra.Command{
 		if err != nil {
 			return errors.Wrapf(err, "Could not expand %s", configFile)
 		}
+		log.Debugf("Reading config from %s", expandedConfigFile)
 
 		conf, err := config.FromFile(expandedConfigFile)
 		if err != nil {
 			return err
 		}
+		log.Debugf("Parsed config is: %s", spew.Sdump(conf))
 
 		sess, err := session.NewSessionWithOptions(
 			session.Options{
@@ -57,6 +64,7 @@ var runCmd = &cobra.Command{
 		mfaTokenProvider := util.TokenProvider("AWS MFA token:")
 		var regionErrors error
 		for _, region := range conf.LambdaConfig.Regions {
+			log.Debugf("Attempting region %s", region.AWSRegion)
 			awsUserSessionProviderConf := &aws.Config{
 				Region: aws.String(region.AWSRegion),
 			}
@@ -84,7 +92,8 @@ var runCmd = &cobra.Command{
 				WithSTS(userConf).
 				WithLambda(roleConf)
 
-			user, err := awsClient.IAM.GetCurrentUser()
+			log.Debugf("Getting current aws iam user")
+			user, err := awsClient.IAM.GetCurrentUser(ctx)
 			if err != nil {
 				return err
 			}
@@ -108,7 +117,7 @@ var runCmd = &cobra.Command{
 			)
 
 			client := bless.New(conf).WithAwsClient(awsClient).WithTokenGenerator(tg).WithUsername(*user.UserName)
-			err = client.RequestCert()
+			err = client.RequestCert(ctx)
 			if err != nil {
 				log.Errorf("Error in region %s: %s. Attempting other regions is available.", region.AWSRegion, err.Error())
 				regionErrors = multierror.Append(regionErrors, err)

pkg/bless/COVERAGE

@@ -1 +1 @@
-78.7
+81.1

pkg/bless/client.go

@@ -1,6 +1,7 @@
 package bless
 
 import (
+	"context"
 	"encoding/json"
 	"strings"
 
@@ -9,6 +10,7 @@ import (
 	"github.com/chanzuckerberg/blessclient/pkg/ssh"
 	"github.com/chanzuckerberg/go-kmsauth"
 	cziAWS "github.com/chanzuckerberg/go-misc/aws"
+	"github.com/davecgh/go-spew/spew"
 	"github.com/pkg/errors"
 	log "github.com/sirupsen/logrus"
 )
@@ -65,13 +67,14 @@ type LambdaResponse struct {
 }
 
 // RequestKMSAuthToken requests a new kmsauth token
-func (c *Client) RequestKMSAuthToken() (*kmsauth.EncryptedToken, error) {
-	token, err := c.tg.GetEncryptedToken()
+func (c *Client) RequestKMSAuthToken(ctx context.Context) (*kmsauth.EncryptedToken, error) {
+	token, err := c.tg.GetEncryptedToken(ctx)
 	return token, errors.Wrap(err, "Error requesting kmsauth token")
 }
 
 // RequestCert requests a cert
-func (c *Client) RequestCert() error {
+func (c *Client) RequestCert(ctx context.Context) error {
+	log.Debugf("Requesting certificate")
 	payload := &LambdaPayload{
 		BastionUser:     c.username,
 		RemoteUsernames: strings.Join(c.conf.ClientConfig.RemoteUsers, ","),
@@ -90,41 +93,46 @@ func (c *Client) RequestCert() error {
 		return err
 	}
 	if isFresh {
-		log.Info("Cert is already fresh - using it")
+		log.Debug("Cert is already fresh - using it")
 		return nil
 	}
-
 	log.Debug("Requesting new cert")
+
 	pubKey, err := s.ReadPublicKey()
 	if err != nil {
 		return err
 	}
+	log.Debugf("Using public key: %s", string(pubKey))
 
-	token, err := c.RequestKMSAuthToken()
+	token, err := c.RequestKMSAuthToken(ctx)
 	if err != nil {
 		return err
 	}
 	if token == nil {
 		return errs.ErrMissingKMSAuthToken
 	}
+	log.Debugf("With KMSAuthToken %s", token.String())
 
 	payload.KMSAuthToken = token.String()
 	payload.PublicKeyToSign = string(pubKey)
+	log.Debugf("Requesting cert with lambda payload %s", spew.Sdump(payload))
 
 	payloadB, err := json.Marshal(payload)
 	if err != nil {
 		return errors.Wrap(err, "Could not serialize lambda payload")
 	}
-	responseBytes, err := c.Aws.Lambda.Execute(c.conf.LambdaConfig.FunctionName, payloadB)
+	responseBytes, err := c.Aws.Lambda.Execute(ctx, c.conf.LambdaConfig.FunctionName, payloadB)
 	if err != nil {
 		return err
 	}
-
+	log.Debugf("Raw lambda response %s", string(responseBytes))
 	lambdaReponse := &LambdaResponse{}
 	err = json.Unmarshal(responseBytes, lambdaReponse)
 	if err != nil {
 		return errors.Wrap(err, "Could not deserialize lambda reponse")
 	}
+	log.Debugf("Parsed lambda response %s", spew.Sdump(lambdaReponse))
+
 	if lambdaReponse.ErrorType != nil {
 		if lambdaReponse.ErrorMessage != nil {
 			return errors.Errorf("bless error: %s: %s", *lambdaReponse.ErrorType, *lambdaReponse.ErrorMessage)

pkg/bless/client_test.go

@@ -1,6 +1,7 @@
 package bless_test
 
 import (
+	"context"
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
@@ -34,6 +35,7 @@ type TestSuite struct {
 	encryptOut       *kms.EncryptOutput
 	lambdaExecuteOut *lambda.InvokeOutput
 	conf             *config.Config
+	ctx              context.Context
 	// cleanup
 	pathsToRemove []string
 	server        *httptest.Server
@@ -48,6 +50,7 @@ func (ts *TestSuite) TearDownTest() {
 func (ts *TestSuite) SetupTest() {
 	t := ts.T()
 	a := assert.New(t)
+	ts.ctx = context.Background()
 
 	conf, pathsToRemove := testConfig(t)
 	ts.pathsToRemove = pathsToRemove
@@ -113,10 +116,10 @@ func (ts *TestSuite) TestEverythingOk() {
 	t := ts.T()
 	a := assert.New(t)
 
-	ts.mockKMS.On("Encrypt", mock.Anything).Return(ts.encryptOut, nil)
-	ts.mockLambda.On("Invoke", mock.Anything).Return(ts.lambdaExecuteOut, nil)
+	ts.mockKMS.On("EncryptWithContext", mock.Anything).Return(ts.encryptOut, nil)
+	ts.mockLambda.On("InvokeWithContext", mock.Anything).Return(ts.lambdaExecuteOut, nil)
 
-	err := ts.client.RequestCert()
+	err := ts.client.RequestCert(ts.ctx)
 	a.Nil(err)
 }
 
@@ -130,7 +133,7 @@ func (ts *TestSuite) TestErrOnMalformedCert() {
 	a.Nil(err)
 	defer os.RemoveAll(certPath)
 
-	err = ts.client.RequestCert()
+	err = ts.client.RequestCert(ts.ctx)
 	a.NotNil(err)
 	a.Contains(err.Error(), "Could not parse cert")
 }
@@ -142,17 +145,17 @@ func (ts *TestSuite) TestFreshCert() {
 	// cert generated as follows:
 	// ssh-keygen -t rsa -f test_key
 	// ssh-keygen -s test_key -I test-cert  -O critical:source-address:0.0.0.0/0 -n test-principal -V -520w:-510w test_key.pub
-	ts.mockKMS.On("Encrypt", mock.Anything).Return(ts.encryptOut, nil)
-	ts.mockLambda.On("Invoke", mock.Anything).Return(ts.lambdaExecuteOut, nil)
+	ts.mockKMS.On("EncryptWithContext", mock.Anything).Return(ts.encryptOut, nil)
+	ts.mockLambda.On("InvokeWithContext", mock.Anything).Return(ts.lambdaExecuteOut, nil)
 	certPath := fmt.Sprintf("%s-cert.pub", ts.conf.ClientConfig.SSHPrivateKey)
 	cert, err := ioutil.ReadFile("testdata/cert")
 	a.Nil(err)
 	err = ioutil.WriteFile(certPath, cert, 0644)
 	a.Nil(err)
 	defer os.RemoveAll(certPath)
-	err = ts.client.RequestCert()
+	err = ts.client.RequestCert(ts.ctx)
 	a.Nil(err)
-	a.True(ts.mockLambda.Mock.AssertNotCalled(t, "Invoke"))
+	a.True(ts.mockLambda.Mock.AssertNotCalled(t, "InvokeWithContext"))
 }
 
 func (ts *TestSuite) TestBadPrincipalsCert() {
@@ -161,17 +164,17 @@ func (ts *TestSuite) TestBadPrincipalsCert() {
 	// cert generated as follows:
 	// ssh-keygen -t rsa -f test_key
 	// ssh-keygen -s test_key -I test-cert  -O critical:source-address:0.0.0.0/0 -n test-principal -V -520w:-510w test_key.pub
-	ts.mockKMS.On("Encrypt", mock.Anything).Return(ts.encryptOut, nil)
-	ts.mockLambda.On("Invoke", mock.Anything).Return(ts.lambdaExecuteOut, nil)
+	ts.mockKMS.On("EncryptWithContext", mock.Anything).Return(ts.encryptOut, nil)
+	ts.mockLambda.On("InvokeWithContext", mock.Anything).Return(ts.lambdaExecuteOut, nil)
 	certPath := fmt.Sprintf("%s-cert.pub", ts.conf.ClientConfig.SSHPrivateKey)
 	cert, err := ioutil.ReadFile("testdata/bad-principal")
 	a.Nil(err)
 	err = ioutil.WriteFile(certPath, cert, 0644)
 	a.Nil(err)
 	defer os.RemoveAll(certPath)
-	err = ts.client.RequestCert()
+	err = ts.client.RequestCert(ts.ctx)
 	a.Nil(err)
-	a.True(ts.mockLambda.Mock.AssertCalled(t, "Invoke", mock.Anything))
+	a.True(ts.mockLambda.Mock.AssertCalled(t, "InvokeWithContext", mock.Anything))
 }
 
 func (ts *TestSuite) TestBadCriticalOptionsCert() {
@@ -180,17 +183,17 @@ func (ts *TestSuite) TestBadCriticalOptionsCert() {
 	// cert generated as follows:
 	// ssh-keygen -t rsa -f test_key
 	// ssh-keygen -s test_key -I test-cert  -O critical:source-address:0.0.0.0/0 -n test-principal -V -520w:-510w test_key.pub
-	ts.mockKMS.On("Encrypt", mock.Anything).Return(ts.encryptOut, nil)
-	ts.mockLambda.On("Invoke", mock.Anything).Return(ts.lambdaExecuteOut, nil)
+	ts.mockKMS.On("EncryptWithContext", mock.Anything).Return(ts.encryptOut, nil)
+	ts.mockLambda.On("InvokeWithContext", mock.Anything).Return(ts.lambdaExecuteOut, nil)
 	certPath := fmt.Sprintf("%s-cert.pub", ts.conf.ClientConfig.SSHPrivateKey)
 	cert, err := ioutil.ReadFile("testdata/bad-critical-options")
 	a.Nil(err)
 	err = ioutil.WriteFile(certPath, cert, 0644)
 	a.Nil(err)
 	defer os.RemoveAll(certPath)
-	err = ts.client.RequestCert()
+	err = ts.client.RequestCert(ts.ctx)
 	a.Nil(err)
-	a.True(ts.mockLambda.Mock.AssertCalled(t, "Invoke", mock.Anything))
+	a.True(ts.mockLambda.Mock.AssertCalled(t, "InvokeWithContext", mock.Anything))
 }
 
 func (ts *TestSuite) TestReportsLambdaErrors() {
@@ -208,10 +211,10 @@ func (ts *TestSuite) TestReportsLambdaErrors() {
 		Payload: lambdaBytes,
 	}
 
-	ts.mockKMS.On("Encrypt", mock.Anything).Return(ts.encryptOut, nil)
-	ts.mockLambda.On("Invoke", mock.Anything).Return(ts.lambdaExecuteOut, nil)
+	ts.mockKMS.On("EncryptWithContext", mock.Anything).Return(ts.encryptOut, nil)
+	ts.mockLambda.On("InvokeWithContext", mock.Anything).Return(ts.lambdaExecuteOut, nil)
 
-	err = ts.client.RequestCert()
+	err = ts.client.RequestCert(ts.ctx)
 	a.NotNil(err)
 	a.Contains(err.Error(), "bless error")
 	a.Contains(err.Error(), *lambdaResponse.ErrorMessage)
@@ -233,10 +236,10 @@ func (ts *TestSuite) TestNoCertificateInResponse() {
 		Payload: lambdaBytes,
 	}
 
-	ts.mockKMS.On("Encrypt", mock.Anything).Return(ts.encryptOut, nil)
-	ts.mockLambda.On("Invoke", mock.Anything).Return(ts.lambdaExecuteOut, nil)
+	ts.mockKMS.On("EncryptWithContext", mock.Anything).Return(ts.encryptOut, nil)
+	ts.mockLambda.On("InvokeWithContext", mock.Anything).Return(ts.lambdaExecuteOut, nil)
 
-	err = ts.client.RequestCert()
+	err = ts.client.RequestCert(ts.ctx)
 	a.NotNil(err)
 	a.Equal(err, errs.ErrNoCertificateInResponse)
 }

pkg/ssh/ssh.go

@@ -13,6 +13,7 @@ import (
 	"github.com/chanzuckerberg/blessclient/pkg/errs"
 	homedir "github.com/mitchellh/go-homedir"
 	"github.com/pkg/errors"
+	log "github.com/sirupsen/logrus"
 	"golang.org/x/crypto/ssh"
 )
 
@@ -108,7 +109,8 @@ func (s *SSH) IsCertFresh(c *config.Config) (bool, error) {
 
 // WriteCert writes a cert to disk
 func (s *SSH) WriteCert(b []byte) error {
-	cert := path.Join(s.sshDirectory, fmt.Sprintf("%s-cert.pub", s.keyName))
-	err := ioutil.WriteFile(cert, b, 0644)
-	return errors.Wrapf(err, "Could not write cert to %s", cert)
+	certPath := path.Join(s.sshDirectory, fmt.Sprintf("%s-cert.pub", s.keyName))
+	log.Debugf("Writing cert to %s", certPath)
+	err := ioutil.WriteFile(certPath, b, 0644)
+	return errors.Wrapf(err, "Could not write cert to %s", certPath)
 }