Repository: Versent/saml2aws
Pull request #73 (2017-10-19 21:57:54)

feat(Logging) Added a verbose flag and logging to providers


Patch:
diff --git a/cmd/saml2aws/commands/login.go b/cmd/saml2aws/commands/login.go
index a40a1d4..39e5aa3 100644
--- a/cmd/saml2aws/commands/login.go
+++ b/cmd/saml2aws/commands/login.go
@@ -43,8 +43,12 @@ func Login(loginFlags *LoginFlags) error {
 		return errors.Wrap(err, "failed to load configuration")
 	}
 
-	account, err := cfgm.LoadIDPAccount(loginFlags.IdpAccount)
+	account, err := cfgm.LoadVerifyIDPAccount(loginFlags.IdpAccount)
 	if err != nil {
+		if cfg.IsErrIdpAccountNotFound(err) {
+			fmt.Printf("%v\n", err)
+			os.Exit(1)
+		}
 		return errors.Wrap(err, "failed to load idp account")
 	}
 
@@ -61,7 +65,7 @@ func Login(loginFlags *LoginFlags) error {
 		os.Exit(1)
 	}
 
-	fmt.Printf("Authenticating as %s ...", account.Username)
+	fmt.Printf("Authenticating as %s ...\n", account.Username)
 
 	provider, err := saml2aws.NewSAMLClient(account)
 	if err != nil {
diff --git a/cmd/saml2aws/main.go b/cmd/saml2aws/main.go
index a6ebea2..bfcba7e 100644
--- a/cmd/saml2aws/main.go
+++ b/cmd/saml2aws/main.go
@@ -2,16 +2,18 @@ package main
 
 import (
 	"fmt"
-	"log"
 	"os"
 
 	"github.com/alecthomas/kingpin"
+	"github.com/sirupsen/logrus"
 	"github.com/versent/saml2aws/cmd/saml2aws/commands"
 )
 
 var (
 	app = kingpin.New("saml2aws", "A command line tool to help with SAML access to the AWS token service.")
 
+	verbose = app.Flag("verbose", "Enable verbose logging").Bool()
+
 	cmdLogin     = app.Command("login", "Login to a SAML 2.0 IDP and convert the SAML assertion to an STS token.")
 	cmdExec      = app.Command("exec", "Exec the supplied command with env vars from STS token.")
 	cmdConfigure = app.Command("configure", "Configure a new IDP account.")
@@ -61,7 +63,6 @@ func configureLoginFlags(app *kingpin.Application) *commands.LoginFlags {
 }
 
 func main() {
-	log.SetFlags(log.Lshortfile)
 
 	app.Version(Version)
 
@@ -69,8 +70,14 @@ func main() {
 
 	command := kingpin.MustParse(app.Parse(os.Args[1:]))
 
+	if *verbose {
+		logrus.SetLevel(logrus.DebugLevel)
+	}
+
 	var err error
 
+	logrus.WithField("command", command).Debug("Running")
+
 	switch command {
 	case cmdLogin.FullCommand():
 		err = commands.Login(lc)
diff --git a/glide.lock b/glide.lock
index 61c0753..3674de6 100644
--- a/glide.lock
+++ b/glide.lock
@@ -1,5 +1,5 @@
 hash: 848f784f129d44ef88c8f0aea25e59205d6a16c172f6da53e8877439ee3c18ea
-updated: 2017-10-16T20:28:20.907066542+11:00
+updated: 2017-10-20T10:15:42.543485072+11:00
 imports:
 - name: github.com/alecthomas/kingpin
   version: d2d8a9115b36a531781f0ed3c57bcba202976150
@@ -40,6 +40,8 @@ imports:
   version: 2d5c7863390875bc4b5f81cdb65422602d15b003
 - name: github.com/beevik/etree
   version: ce53c4ce608a92897d74ff8fd47b5a1131e5606c
+- name: github.com/fatih/structs
+  version: 7e5a8eef611ee84dd359503f3969f80df4c50723
 - name: github.com/go-ini/ini
   version: 6e4869b434bd001f6983749881c7ead3545887d8
 - name: github.com/howeyc/gopass
@@ -54,6 +56,8 @@ imports:
   version: 152b1a2c8f5d0340f658bb656032a39b94e52958
 - name: github.com/segmentio/go-prompt
   version: f3218e418a3d6dbe1dcab5809d80fa6e15c05cb4
+- name: github.com/sirupsen/logrus
+  version: 89742aefa4b206dcf400792f3bd35b542998eb3b
 - name: github.com/tidwall/gjson
   version: 039b641eabfaaccef32ebcfeee4257e22627a255
 - name: github.com/tidwall/match
diff --git a/helper/osxkeychain/osxkeychain_darwin.go b/helper/osxkeychain/osxkeychain_darwin.go
index 863b7cb..788e894 100644
--- a/helper/osxkeychain/osxkeychain_darwin.go
+++ b/helper/osxkeychain/osxkeychain_darwin.go
@@ -15,9 +15,12 @@ import (
 	"strings"
 	"unsafe"
 
+	"github.com/sirupsen/logrus"
 	"github.com/versent/saml2aws/helper/credentials"
 )
 
+var logger = logrus.WithField("helper", "osxkeychain")
+
 // errCredentialsNotFound is the specific error message returned by OS X
 // when the credentials are not in the keychain.
 const errCredentialsNotFound = "The specified item could not be found in the keychain."
@@ -70,6 +73,9 @@ func (h Osxkeychain) Delete(serverURL string) error {
 
 // Get returns the username and secret to use for a given registry server URL.
 func (h Osxkeychain) Get(serverURL string) (string, string, error) {
+
+	logger.WithField("serverURL", serverURL).Debug("Get credentials")
+
 	s, err := splitServer(serverURL)
 	if err != nil {
 		return "", "", err
@@ -88,6 +94,7 @@ func (h Osxkeychain) Get(serverURL string) (string, string, error) {
 		defer C.free(unsafe.Pointer(errMsg))
 		goMsg := C.GoString(errMsg)
 		if goMsg == errCredentialsNotFound {
+			logger.WithField("goMsg", goMsg).Debug("Get credentials")
 			return "", "", credentials.ErrCredentialsNotFound
 		}
 
@@ -96,6 +103,9 @@ func (h Osxkeychain) Get(serverURL string) (string, string, error) {
 
 	user := C.GoStringN(username, C.int(usernameLen))
 	pass := C.GoStringN(secret, C.int(secretLen))
+
+	logger.WithField("user", user).Debug("Get credentials")
+
 	return user, pass, nil
 }
 
diff --git a/pkg/cfg/cfg.go b/pkg/cfg/cfg.go
index c6633ad..a3c2ef4 100644
--- a/pkg/cfg/cfg.go
+++ b/pkg/cfg/cfg.go
@@ -1,11 +1,15 @@
 package cfg
 
 import (
+	"github.com/fatih/structs"
 	"github.com/mitchellh/go-homedir"
 	"github.com/pkg/errors"
 	ini "gopkg.in/ini.v1"
 )
 
+// ErrIdpAccountNotFound returned if the idp account is not found in the configuration file
+var ErrIdpAccountNotFound = errors.New("IDP account not found, run configure to set it up")
+
 // DefaultConfigPath the default saml2aws configuration path
 var DefaultConfigPath = "~/.saml2aws"
 
@@ -67,18 +71,48 @@ func (cm *ConfigManager) SaveIDPAccount(idpAccountName string, account *IDPAccou
 // LoadIDPAccount load the idp account and default to an empty one if it doesn't exist
 func (cm *ConfigManager) LoadIDPAccount(idpAccountName string) (*IDPAccount, error) {
 
-	account := new(IDPAccount)
+	cfg, err := ini.LoadSources(ini.LoadOptions{Loose: true}, cm.configPath)
+	if err != nil {
+		return nil, errors.Wrap(err, "Unable to load configuration file")
+	}
+
+	return readAccount(idpAccountName, cfg)
+}
+
+// LoadVerifyIDPAccount load the idp account and verify it isn't empty
+func (cm *ConfigManager) LoadVerifyIDPAccount(idpAccountName string) (*IDPAccount, error) {
 
 	cfg, err := ini.LoadSources(ini.LoadOptions{Loose: true}, cm.configPath)
 	if err != nil {
 		return nil, errors.Wrap(err, "Unable to load configuration file")
 	}
 
+	account, err := readAccount(idpAccountName, cfg)
+	if err != nil {
+		return nil, errors.Wrap(err, "Unable to read idp account")
+	}
+
+	if structs.IsZero(account) {
+		return nil, ErrIdpAccountNotFound
+	}
+
+	return account, nil
+}
+
+// IsErrIdpAccountNotFound check if the error is a ErrIdpAccountNotFound
+func IsErrIdpAccountNotFound(err error) bool {
+	return err == ErrIdpAccountNotFound
+}
+
+func readAccount(idpAccountName string, cfg *ini.File) (*IDPAccount, error) {
+
+	account := new(IDPAccount)
+
 	sec := cfg.Section(idpAccountName)
 
-	err = sec.MapTo(account)
+	err := sec.MapTo(account)
 	if err != nil {
-		return nil, errors.Wrap(err, "Unable to load configuration file")
+		return nil, errors.Wrap(err, "Unable to map account")
 	}
 
 	return account, nil
diff --git a/pkg/dump/dump.go b/pkg/dump/dump.go
new file mode 100644
index 0000000..2821862
--- /dev/null
+++ b/pkg/dump/dump.go
@@ -0,0 +1,26 @@
+package dump
+
+import (
+	"net/http"
+	"net/http/httputil"
+)
+
+func RequestString(req *http.Request) string {
+	data, err := httputil.DumpRequest(req, false)
+
+	if err != nil {
+		return ""
+	}
+
+	return string(data)
+}
+
+func ResponseString(res *http.Response) string {
+	data, err := httputil.DumpResponse(res, false)
+
+	if err != nil {
+		return ""
+	}
+
+	return string(data)
+}
diff --git a/pkg/provider/pingfed/pingfed.go b/pkg/provider/pingfed/pingfed.go
index aa374f0..d911f93 100644
--- a/pkg/provider/pingfed/pingfed.go
+++ b/pkg/provider/pingfed/pingfed.go
@@ -10,11 +10,15 @@ import (
 	"github.com/PuerkitoBio/goquery"
 	"github.com/pkg/errors"
 	prompt "github.com/segmentio/go-prompt"
+	"github.com/sirupsen/logrus"
 	"github.com/versent/saml2aws/pkg/cfg"
 	"github.com/versent/saml2aws/pkg/creds"
+	"github.com/versent/saml2aws/pkg/dump"
 	"github.com/versent/saml2aws/pkg/provider"
 )
 
+var logger = logrus.WithField("provider", "pingfed")
+
 // Client wrapper around PingFed + PingId enabling authentication and retrieval of assertions
 type Client struct {
 	client        *provider.HTTPClient
@@ -51,6 +55,8 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 
 	pingFedURL := fmt.Sprintf("https://%s/idp/startSSO.ping?PartnerSpId=urn:amazon:webservices", loginDetails.Hostname)
 
+	logger.WithField("url", pingFedURL).Debug("GET")
+
 	res, err := ac.client.Get(pingFedURL)
 	if err != nil {
 		return "", errors.Wrap(err, "error retieving form")
@@ -90,30 +96,47 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 
 	req.Header.Add("Content-Type", "application/x-www-form-urlencoded")
 
+	logger.WithField("authSubmitURL", ac.authSubmitURL).WithField("req", dump.RequestString(req)).Debug("POST")
+
 	res, err = ac.client.Do(req)
 	if err != nil {
-		//check for redirect, this indicates PingOne MFA being used
-		if res.StatusCode == 302 {
-			ac.mfaRequired = true
-		} else {
-			return "", errors.Wrap(err, "error retieving login form")
-		}
+		return "", errors.Wrap(err, "error retrieving login form")
+	}
+
+	logger.WithField("authSubmitURL", ac.authSubmitURL).WithField("res", dump.ResponseString(res)).Debug("POST")
+
+	//check for redirect, this indicates PingOne MFA being used
+	if res.StatusCode == 302 {
+		ac.mfaRequired = true
 	}
 
+	logger.WithField("mfaRequired", ac.mfaRequired).Debug("POST")
+
 	//process mfa
 	if ac.mfaRequired {
 
 		mfaURL, err := res.Location()
+		if err != nil {
+			return "", errors.Wrap(err, "error building mfa url")
+		}
 		//spew.Dump(mfaURL)
+		logger.WithField("mfaURL", mfaURL).Debug("GET")
 
 		//follow redirect
 		res, err = ac.client.Get(mfaURL.String())
 		if err != nil {
-			return "", errors.Wrap(err, "error retieving form")
+			return "", errors.Wrap(err, "error retrieving form")
 		}
 
+		logger.WithField("mfaURL", mfaURL).WithField("res", dump.ResponseString(res)).Debug("GET")
+
 		//extract form action and jwt token
 		form, actionURL, err := extractFormData(res)
+		if err != nil {
+			return "", errors.Wrap(err, "error extracting mfa form data")
+		}
+
+		logger.WithField("actionURL", actionURL).Debug("POST")
 
 		//request mfa auth via PingId (device swipe)
 		req, err := http.NewRequest("POST", actionURL, strings.NewReader(form.Encode()))
@@ -127,6 +150,8 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 			return "", errors.Wrap(err, "error retieving mfa response")
 		}
 
+		logger.WithField("actionURL", actionURL).WithField("res", dump.ResponseString(res)).Debug("POST")
+
 		//extract form action and csrf token
 		form, actionURL, err = extractFormData(res)
 
@@ -144,6 +169,11 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 
 		//extract form action and jwt token
 		form, actionURL, err = extractFormData(res)
+		if err != nil {
+			return "", errors.Wrap(err, "error extracting jwt form data")
+		}
+
+		logger.WithField("actionURL", actionURL).Debug("POST")
 
 		//if actionURL is OTP then prompt for token
 		//user has disabled swipe
@@ -162,13 +192,21 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 			}
 
 			req.Header.Add("Content-Type", "application/x-www-form-urlencoded")
+
+			logger.WithField("actionURL", actionURL).WithField("req", dump.RequestString(req)).Debug("POST")
+
 			res, err = ac.client.Do(req)
 			if err != nil {
 				return "", errors.Wrap(err, "error polling mfa device")
 			}
 
+			logger.WithField("actionURL", actionURL).WithField("res", dump.ResponseString(res)).Debug("POST")
+
 			//extract form action and jwt token
 			form, actionURL, err = extractFormData(res)
+			if err != nil {
+				return "", errors.Wrap(err, "error extracting mfa form data")
+			}
 
 		}
 
@@ -180,11 +218,14 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 
 		req.Header.Add("Content-Type", "application/x-www-form-urlencoded")
 
+		logger.WithField("actionURL", actionURL).WithField("req", dump.RequestString(req)).Debug("POST")
+
 		res, err = ac.client.Do(req)
 		if err != nil {
 			return "", errors.Wrap(err, "error authenticating mfa")
 		}
 
+		logger.WithField("actionURL", actionURL).WithField("res", dump.ResponseString(res)).Debug("POST")
 	}
 
 	//try to extract SAMLResponse
@@ -200,6 +241,8 @@ func (ac *Client) Authenticate(loginDetails *creds.LoginDetails) (string, error)
 		return "", errors.Wrap(err, "unable to locate saml response")
 	}
 
+	logger.WithField("samlAssertion", ac.samlAssertion).Debug("SAMLResponse")
+
 	return ac.samlAssertion, nil
 }
 


Test patch:
diff --git a/pkg/cfg/cfg_test.go b/pkg/cfg/cfg_test.go
index 73854e8..d6c0132 100644
--- a/pkg/cfg/cfg_test.go
+++ b/pkg/cfg/cfg_test.go
@@ -33,6 +33,22 @@ func TestNewConfigManagerLoad(t *testing.T) {
 	require.Equal(t, &IDPAccount{}, idpAccount)
 }
 
+func TestNewConfigManagerLoadVerify(t *testing.T) {
+
+	cfgm, err := NewConfigManager("example/saml2aws.ini")
+	require.Nil(t, err)
+
+	require.NotNil(t, cfgm)
+
+	idpAccount, err := cfgm.LoadIDPAccount("test123")
+	require.Nil(t, err)
+	require.Equal(t, &IDPAccount{Hostname: "id.whatever.com", Username: "abc@whatever.com", Provider: "keycloak", MFA: "sms"}, idpAccount)
+
+	idpAccount, err = cfgm.LoadVerifyIDPAccount("test1234")
+	require.Equal(t, err, ErrIdpAccountNotFound)
+	require.Nil(t, idpAccount)
+}
+
 func TestNewConfigManagerSave(t *testing.T) {
 
 	cfgm, err := NewConfigManager(throwAwayConfig)