Add trace logging and remove kong

cmd/sshrimp-agent/main.go

@@ -5,6 +5,7 @@ import (
 	"crypto/rand"
 	"crypto/rsa"
 	"errors"
+	"flag"
 	"fmt"
 	"io"
 	"net"
@@ -13,50 +14,80 @@ import (
 	"strings"
 	"syscall"
 
-	"github.com/alecthomas/kong"
+	"github.com/sirupsen/logrus"
-
 	"github.com/stoggi/sshrimp/internal/config"
+	"github.com/stoggi/sshrimp/internal/signer"
 	"github.com/stoggi/sshrimp/internal/sshrimpagent"
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/crypto/ssh/agent"
 )
 
 var sigs = []os.Signal{os.Kill, os.Interrupt}
+var logger = logrus.New()
+var log *logrus.Entry
 
 var cli struct {
 	Config string `kong:"arg,type='string',help='sshrimp config file (default: ${config_file} or ${env_var_name} environment variable)',default='${config_file}',env='SSHRIMP_CONFIG'"`
 }
 
 func main() {
-	ctx := kong.Parse(&cli,
+	flag.StringVar(&cli.Config, "config", config.DefaultPath, "sshrimp config file")
-		kong.Name("sshrimp-agent"),
+	v := flag.Bool("v", false, "enable verbose logging")
-		kong.Description("An SSH Agent that renews SSH certificates automatically from a SSHrimp Certificate Authority."),
+
-		kong.Vars{
+	logger.SetFormatter(&logrus.TextFormatter{
-			"config_file":  config.DefaultPath,
+		FullTimestamp: true,
-			"env_var_name": config.EnvVarName,
+	})
-		},
+	log = logger.WithFields(logrus.Fields{
-	)
+		"pid": os.Getpid(),
+	})
+	sshrimpagent.Log = log
+	signer.Log = log
+
+	flag.Parse()
+
+	if *v {
+		logger.SetLevel(logrus.TraceLevel)
+	}
 
 	c := config.NewSSHrimpWithDefaults()
-	ctx.FatalIfErrorf(c.Read(cli.Config))
+	err := c.Read(cli.Config)
-	ctx.FatalIfErrorf(launchAgent(c, ctx))
+	if err != nil {
+		panic(err)
+	}
+	err = launchAgent(c)
+	if err != nil {
+		panic(err)
+	}
 }
 
-func launchAgent(c *config.SSHrimp, ctx *kong.Context) error {
+func launchAgent(c *config.SSHrimp) error {
 	var (
 		err        error
 		listener   net.Listener
 		privateKey crypto.Signer
 		signer     ssh.Signer
+		logMessage string
 	)
 
+	log.Traceln("Creating socket")
 	if _, err = os.Stat(c.Agent.Socket); err == nil {
+		log.Tracef("File already exists at %s", c.Agent.Socket)
 		conn, sockErr := net.Dial("unix", c.Agent.Socket)
+		if conn == nil {
+			logMessage = "conn is nil"
+		}
 		if sockErr == nil { // socket is accepting connections
+			logMessage += "err reports successful connection"
 			conn.Close()
+			log.Errorf("Socket connected successfully %s", logMessage)
 			return fmt.Errorf("socket %s already exists", c.Agent.Socket)
 		}
-		os.Remove(c.Agent.Socket) // socket is not accepting connections, assuming safe to remove
+		log.Tracef("Socket is not connected %s", logMessage)
+		if os.Remove(c.Agent.Socket) == nil { // socket is not accepting connections, assuming safe to remove
+			log.Traceln("Deleting socket: success")
+		} else {
+			log.Errorf("Deleting socket: fail")
+		}
 	}
 
 	// This affects all files created for the process. Since this is a sensitive
@@ -68,41 +99,49 @@ func launchAgent(c *config.SSHrimp, ctx *kong.Context) error {
 	}
 	defer listener.Close()
 
-	ctx.Printf("listening on %s", c.Agent.Socket)
+	fmt.Printf("listening on %s\n", c.Agent.Socket)
 
 	// Generate a new SSH private/public key pair
+	log.Tracef("Generating RSA %d ssh keys", 2048)
 	privateKey, err = rsa.GenerateKey(rand.Reader, 2048)
 	if err != nil {
 		return err
 	}
+	log.Traceln("Creating new signer from key")
 	signer, err = ssh.NewSignerFromKey(privateKey)
 	if err != nil {
 		return err
 	}
 
 	// Create the sshrimp agent with our configuration and the private key signer
+	log.Traceln("Creating new sshrimp agent from signer and config")
 	sshrimpAgent := sshrimpagent.NewSSHrimpAgent(c, signer)
 
 	// Listen for signals so that we can close the listener and exit nicely
+	log.Debugf("Exiting on signals: %v", sigs)
 	osSignals := make(chan os.Signal)
 	signal.Notify(osSignals, sigs...)
 	go func() {
-		_ = <-osSignals
+		<-osSignals
 		listener.Close()
 	}()
 
+	log.Traceln("Starting main loop")
 	// Accept connections and serve the agent
 	for {
 		var conn net.Conn
 		conn, err = listener.Accept()
 		if err != nil {
+			log.Errorf("Error accepting connection: %v", err)
 			if strings.Contains(err.Error(), "use of closed network connection") {
 				// Occurs if the user interrupts the agent with a ctrl-c signal
 				return nil
 			}
 			return err
 		}
+		log.Traceln("Serving agent")
 		if err = agent.ServeAgent(sshrimpAgent, conn); err != nil && !errors.Is(err, io.EOF) {
+			log.Errorf("Error serving agent: %v", err)
 			return err
 		}
 	}

cmd/sshrimp-agent/unix.go

@@ -1,4 +1,5 @@
 // +build darwin linux
+
 package main
 
 import (

internal/signer/sshrimp.go

@@ -18,12 +18,15 @@ import (
 	"github.com/aws/aws-sdk-go/aws/session"
 	"github.com/aws/aws-sdk-go/service/lambda"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"github.com/stoggi/sshrimp/internal/config"
 	"github.com/stoggi/sshrimp/internal/identity"
 
 	"golang.org/x/crypto/ssh"
 )
 
+var Log *logrus.Entry
+
 // SSHrimpResult encodes the payload format returned from the sshrimp-ca lambda
 type SSHrimpResult struct {
 	Certificate  string `json:"certificate"`
@@ -63,7 +66,6 @@ func SignCertificateAllRegions(publicKey ssh.PublicKey, token string, forceComma
 
 // SignCertificateGCP given a public key, identity token and forceCommand, invoke the sshrimp-ca GCP function
 func SignCertificateGCP(publicKey ssh.PublicKey, token string, forceCommand string, region string, c *config.SSHrimp) (*ssh.Certificate, error) {
-
 	// Setup the JSON payload for the SSHrimp CA
 	payload, err := json.Marshal(SSHrimpEvent{
 		PublicKey:    string(ssh.MarshalAuthorizedKey(publicKey)),
@@ -78,10 +80,6 @@ func SignCertificateGCP(publicKey ssh.PublicKey, token string, forceCommand stri
 	if err != nil {
 		return nil, errors.Wrap(err, "http post failed: "+err.Error())
 	}
-	if result.StatusCode != 200 {
-		return nil, fmt.Errorf("sshrimp returned status code %d", result.StatusCode)
-	}
-
 	resbody, err := ioutil.ReadAll(result.Body)
 	if err != nil {
 		return nil, errors.Wrap(err, "failed to retrieve the response from sshrimp-ca")
@@ -91,7 +89,11 @@ func SignCertificateGCP(publicKey ssh.PublicKey, token string, forceCommand stri
 	sshrimpResult := SSHrimpResult{}
 	err = json.Unmarshal(resbody, &sshrimpResult)
 	if err != nil {
-		return nil, errors.Wrap(err, "failed to parse json response from sshrimp-ca")
+		return nil, errors.Wrap(err, "failed to parse json response from sshrimp-ca.: "+string(resbody))
+	}
+	Log.Traceln("SSHrimpResult:", sshrimpResult)
+	if result.StatusCode != 200 {
+		return nil, fmt.Errorf("sshrimp returned status code %d. Message: %s", result.StatusCode, string(resbody))
 	}
 
 	// These error types and messages can also come from the aws-sdk-go lambda handler
@@ -165,7 +167,7 @@ func ValidateRequest(event SSHrimpEvent, c *config.SSHrimp, requestID string, fu
 	}
 
 	// Validate the user supplied identity token with the loaded configuration
-	i, err := identity.NewIdentity(c)
+	i, _ := identity.NewIdentity(c)
 	username, err := i.Validate(event.Token)
 	if err != nil {
 		return ssh.Certificate{}, err

internal/sshrimpagent/sshrimpagent.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"time"
 
+	"github.com/sirupsen/logrus"
 	"github.com/stoggi/aws-oidc/provider"
 	"github.com/stoggi/sshrimp/internal/config"
 	"github.com/stoggi/sshrimp/internal/signer"
@@ -12,6 +13,8 @@ import (
 	"golang.org/x/crypto/ssh/agent"
 )
 
+var Log *logrus.Entry
+
 type sshrimpAgent struct {
 	providerConfig provider.ProviderConfig
 	signer         ssh.Signer
@@ -43,6 +46,7 @@ func NewSSHrimpAgent(c *config.SSHrimp, signer ssh.Signer) agent.Agent {
 
 // RemoveAll clears the current certificate and identity token (including refresh token)
 func (r *sshrimpAgent) RemoveAll() error {
+	Log.Debugln("Removing identity token and certificate")
 	r.certificate = &ssh.Certificate{}
 	r.token = &provider.OAuth2Token{}
 	return nil
@@ -65,18 +69,24 @@ func (r *sshrimpAgent) Unlock(passphrase []byte) error {
 
 // List returns the identities, but also signs the certificate using sshrimp-ca if expired.
 func (r *sshrimpAgent) List() ([]*agent.Key, error) {
+	Log.Traceln("Listing current identities")
 
 	unixNow := time.Now().Unix()
 	before := int64(r.certificate.ValidBefore)
 	if r.certificate.ValidBefore != uint64(ssh.CertTimeInfinity) && (unixNow >= before || before < 0) {
 		// Certificate has expired
+		Log.Traceln("Certificate has expired")
+		Log.Traceln("authenticating token")
 		err := r.providerConfig.Authenticate(r.token)
 		if err != nil {
+			Log.Errorf("authenticating the token failed: %v", err)
 			return nil, err
 		}
 
+		Log.Traceln("signing certificate")
 		cert, err := signer.SignCertificateAllRegions(r.signer.PublicKey(), r.token.IDToken, "", r.config)
 		if err != nil {
+			Log.Errorf("signing certificate failed: %v", err)
 			return nil, err
 		}
 		r.certificate = cert
@@ -109,21 +119,28 @@ func (r *sshrimpAgent) Signers() ([]ssh.Signer, error) {
 }
 
 func (r *sshrimpAgent) SignWithFlags(key ssh.PublicKey, data []byte, flags agent.SignatureFlags) (*ssh.Signature, error) {
+	Log.Traceln("requested sign with flags")
 	sign, ok := r.signer.(ssh.AlgorithmSigner)
+	Log.Tracef("signer is AlgorithmSigner: %v", ok)
 	if ok {
 		if flags&agent.SignatureFlagRsaSha512 == agent.SignatureFlagRsaSha512 {
+			Log.Traceln("sha 512 requested")
 			s, err := sign.SignWithAlgorithm(rand.Reader, data, ssh.SigAlgoRSASHA2512)
 			if err == nil {
-				return s, err
+				Log.Debugln("sha 512 available:", err)
+				return s, nil
 			}
 		}
 		if flags&agent.SignatureFlagRsaSha256 == agent.SignatureFlagRsaSha256 {
+			Log.Traceln("sha 256 requested")
 			s, err := sign.SignWithAlgorithm(rand.Reader, data, ssh.SigAlgoRSASHA2256)
 			if err == nil {
-				return s, err
+				Log.Debugln("sha 256 available:", err)
+				return s, nil
 			}
 		}
 	}
+	Log.Traceln("signing data")
 	return r.Sign(key, data)
 }
 func (r *sshrimpAgent) Extension(extensionType string, contents []byte) ([]byte, error) {