Merge pull request #49 from keybase/david/keybaseca-debug-mode

keybaseca debug mode

Author: ddworken

src/cmd/keybaseca/keybaseca.go

@@ -23,6 +23,7 @@ import (
 	"github.com/keybase/bot-sshca/src/kssh"
 	"github.com/keybase/bot-sshca/src/shared"
 
+	"github.com/sirupsen/logrus"
 	"github.com/urfave/cli"
 )
 
@@ -34,6 +35,10 @@ func main() {
 	app.Usage = "An SSH CA built on top of Keybase"
 	app.Version = VersionNumber
 	app.Flags = []cli.Flag{
+		cli.BoolFlag{
+			Name:  "debug",
+			Usage: "Log debug information",
+		},
 		cli.BoolFlag{
 			Name:   "wipe-all-configs",
 			Hidden: true,
@@ -50,6 +55,7 @@ func main() {
 			Name:   "backup",
 			Usage:  "Print the current CA private key to stdout for backup purposes",
 			Action: backupAction,
+			Before: beforeAction,
 		},
 		{
 			Name:  "generate",
@@ -60,11 +66,13 @@ func main() {
 				},
 			},
 			Action: generateAction,
+			Before: beforeAction,
 		},
 		{
 			Name:   "service",
 			Usage:  "Start the CA service in the foreground",
 			Action: serviceAction,
+			Before: beforeAction,
 		},
 		{
 			Name:  "sign",
@@ -81,6 +89,7 @@ func main() {
 				},
 			},
 			Action: signAction,
+			Before: beforeAction,
 		},
 	}
 	app.Action = mainAction
@@ -190,6 +199,14 @@ func signAction(c *cli.Context) error {
 	return nil
 }
 
+// A global before action that handles the --debug flag by setting the logrus logging level
+func beforeAction(c *cli.Context) error {
+	if c.GlobalBool("debug") {
+		logrus.SetLevel(logrus.DebugLevel)
+	}
+	return nil
+}
+
 // The action for the `keybaseca` command. Only used for hidden and unlisted flags.
 func mainAction(c *cli.Context) error {
 	switch {
@@ -280,6 +297,8 @@ func writeClientConfig(conf config.Config) error {
 		}
 	}
 
+	logrus.Debugf("Wrote kssh client config files for the teams: %v", teams)
+
 	return nil
 }
 
@@ -299,6 +318,9 @@ func deleteClientConfig(conf config.Config) error {
 			return err
 		}
 	}
+
+	logrus.Debugf("Deleted kssh client config files for the teams: %v", teams)
+
 	return nil
 }
 

src/keybaseca/bot/bot.go

@@ -7,13 +7,15 @@ import (
 
 	"github.com/keybase/bot-sshca/src/keybaseca/botwrapper"
 
-	"github.com/keybase/bot-sshca/src/keybaseca/log"
+	auditlog "github.com/keybase/bot-sshca/src/keybaseca/log"
 
 	"github.com/keybase/bot-sshca/src/keybaseca/sshutils"
 
 	"github.com/keybase/bot-sshca/src/keybaseca/config"
 	"github.com/keybase/bot-sshca/src/shared"
 	"github.com/keybase/go-keybase-chat-bot/kbchat"
+
+	log "github.com/sirupsen/logrus"
 )
 
 // Get a running instance of the keybase chat API. Will use the configured credentials if necessary.
@@ -53,27 +55,41 @@ func StartBot(conf config.Config) error {
 			return fmt.Errorf("failed to read message: %v", err)
 		}
 
-		if msg.Message.Content.Type != "text" || msg.Message.Sender.Username == kbc.GetUsername() {
+		if msg.Message.Content.Type != "text" {
+			continue
+		}
+
+		messageBody := msg.Message.Content.Text.Body
+
+		log.Debugf("Received message in %s#%s: %s", msg.Message.Channel.Name, msg.Message.Channel.TopicName, messageBody)
+
+		if msg.Message.Sender.Username == kbc.GetUsername() {
+			log.Debug("Skipping message since it comes from the bot user")
+			if strings.Contains(messageBody, shared.AckRequestPrefix) || strings.Contains(messageBody, shared.SignatureRequestPreamble) {
+				log.Warn("Ignoring AckRequest/SignatureRequest coming from the bot user! Are you trying to run the bot " +
+					"and kssh as the same user?")
+			}
 			continue
 		}
 
 		// Note that this line is one of the main security barriers around the SSH bot. If this line were removed
 		// or had a bug, it would cause the SSH bot to respond to any SignatureRequest messages in any channels. This
 		// would allow an attacker to provision SSH keys even though they are not in the listed channels.
 		if !isConfiguredTeam(conf, msg.Message.Channel.Name, msg.Message.Channel.TopicName) {
+			log.Debug("Skipping message since it is not in a configured team")
 			continue
 		}
 
-		messageBody := msg.Message.Content.Text.Body
-
 		if shared.IsAckRequest(messageBody) {
+			log.Debug("Responding to AckMessage")
 			// Ack any AckRequests so that kssh can determine whether it has fully connected
 			_, err = kbc.SendMessageByConvID(msg.Message.ConversationID, shared.GenerateAckResponse(messageBody))
 			if err != nil {
 				LogError(conf, kbc, msg, err)
 				continue
 			}
 		} else if strings.HasPrefix(messageBody, shared.SignatureRequestPreamble) {
+			log.Debug("Responding to SignatureRequest")
 			signatureRequest, err := shared.ParseSignatureRequest(messageBody)
 			if err != nil {
 				LogError(conf, kbc, msg, err)
@@ -97,6 +113,8 @@ func StartBot(conf config.Config) error {
 				LogError(conf, kbc, msg, err)
 				continue
 			}
+		} else {
+			log.Debug("Ignoring unparsed message")
 		}
 	}
 }
@@ -105,10 +123,10 @@ func StartBot(conf config.Config) error {
 // due to an error caused by a malformed message.
 func LogError(conf config.Config, kbc *kbchat.API, msg kbchat.SubscriptionMessage, err error) {
 	message := fmt.Sprintf("Encountered error while processing message from %s (messageID:%d): %v", msg.Message.Sender.Username, msg.Message.MsgID, err)
-	log.Log(conf, message)
+	auditlog.Log(conf, message)
 	_, e := kbc.SendMessageByConvID(msg.Message.ConversationID, message)
 	if e != nil {
-		log.Log(conf, fmt.Sprintf("failed to log an error to chat (something is probably very wrong): %v", err))
+		auditlog.Log(conf, fmt.Sprintf("failed to log an error to chat (something is probably very wrong): %v", err))
 	}
 }
 

src/keybaseca/config/config.go

@@ -11,6 +11,8 @@ import (
 	"github.com/keybase/bot-sshca/src/keybaseca/botwrapper"
 
 	"github.com/keybase/bot-sshca/src/shared"
+
+	log "github.com/sirupsen/logrus"
 )
 
 // Represents a loaded and validated config for keybaseca
@@ -25,6 +27,7 @@ type Config interface {
 	GetChannelName() string
 	GetLogLocation() string
 	GetStrictLogging() bool
+	DebugString() string
 }
 
 // Validate the given config file. If offline, do so without connecting to keybase (used in code that is meant
@@ -58,6 +61,7 @@ func ValidateConfig(conf EnvConfig, offline bool) error {
 			return fmt.Errorf("STRICT_LOGGING must be either 'true' or 'false', '%s' is not valid", conf.getStrictLogging())
 		}
 	}
+	log.Debugf("Validated config: %s", conf.DebugString())
 	return nil
 }
 
@@ -217,6 +221,14 @@ func (ef *EnvConfig) GetChannelName() string {
 	return channel
 }
 
+// Dump this EnvConfig to a string for debugging purposes
+func (ef *EnvConfig) DebugString() string {
+	return fmt.Sprintf("CAKeyLocation='%s'; KeybaseHomeDir='%s'; KeybasePaperKey='%s'; KeybaseUsername='%s'; "+
+		"KeyExpiration='%s'; Teams='%s'; ChatTeam='%s'; ChannelName='%s'; LogLocation='%s'; StrictLogging='%s'",
+		ef.GetCAKeyLocation(), ef.GetKeybaseHomeDir(), ef.GetKeybasePaperKey(), ef.GetKeybaseUsername(),
+		ef.GetKeyExpiration(), ef.GetTeams(), ef.GetChatTeam(), ef.GetChannelName(), ef.GetLogLocation(), ef.getStrictLogging())
+}
+
 // Split a teamChannel of the form team.foo.bar#chan into "team.foo.bar", "chan"
 func splitTeamChannel(teamChannel string) (string, string, error) {
 	split := strings.Split(teamChannel, "#")

src/shared/chat_types.go

@@ -59,9 +59,11 @@ func ParseSignatureResponse(body string) (SignatureResponse, error) {
 	return sr, err
 }
 
+const AckRequestPrefix = "AckRequest--"
+
 // Generate an AckRequest for the given username
 func GenerateAckRequest(username string) string {
-	return "AckRequest--" + username
+	return AckRequestPrefix + username
 }
 
 // Generate an AckResponse in response to the given ack request
@@ -71,7 +73,7 @@ func GenerateAckResponse(ackRequest string) string {
 
 // Returns whether the given message is an ack request
 func IsAckRequest(msg string) bool {
-	return strings.HasPrefix(msg, "AckRequest--")
+	return strings.HasPrefix(msg, AckRequestPrefix)
 }
 
 // Returns whether the given message is an ack response