Merge pull request #126 from grafana/undef1nd/ssh-logging

`Breaking change`: Change logging to enable parsing metrics from log lines

cmd/pdc/main.go

@@ -65,17 +65,6 @@ func (mf *mainFlags) RegisterFlags(fs *flag.FlagSet) {
 	fs.BoolVar(&mf.DevMode, "dev-mode", false, "[DEVELOPMENT ONLY] run the agent in development mode")
 }
 
-func logLevelToSSHLogLevel(level string) (int, error) {
-	switch level {
-	case "error", "warn", "info":
-		return 0, nil
-	case "debug":
-		return 3, nil
-	default:
-		return -1, fmt.Errorf("invalid log level: %s", level)
-	}
-}
-
 // Tries to get the openssh version. Returns "UNKNOWN" on error.
 func tryGetOpenSSHVersion() string {
 	timeoutCtx, cancel := context.WithTimeout(context.Background(), 1*time.Second)
@@ -107,13 +96,6 @@ func main() {
 	}
 
 	sshConfig.Args = os.Args[1:]
-	sshConfig.LogLevel, err = logLevelToSSHLogLevel(mf.LogLevel)
-	if err != nil {
-		usageFn()
-		fmt.Printf("setting log level: %s\n", err)
-		os.Exit(1)
-	}
-
 	logger := setupLogger(mf.LogLevel)
 
 	level.Info(logger).Log("msg", "PDC agent info",
@@ -150,6 +132,7 @@ func main() {
 	pdcClientCfg.URL = apiURL
 	sshConfig.PDC = *pdcClientCfg
 	sshConfig.URL = gatewayURL
+	sshConfig.LogLevel = mf.LogLevel
 
 	if mf.DevMode {
 		setDevelopmentConfig(mf.Domain, sshConfig, pdcClientCfg)

pkg/ssh/ssh.go

@@ -38,7 +38,7 @@ type Config struct {
 	KeyFile           string
 	SSHFlags          []string // Additional flags to be passed to ssh(1). e.g. --ssh-flag="-vvv" --ssh-flag="-L 80:localhost:80"
 	Port              int
-	LogLevel          int
+	LogLevel          string
 	PDC               pdc.Config
 	LegacyMode        bool
 	SkipSSHValidation bool
@@ -67,24 +67,17 @@ func DefaultConfig() *Config {
 	}
 	return &Config{
 		Port:     22,
-		LogLevel: 2,
 		PDC:      pdc.Config{},
+		LogLevel: "info",
 		KeyFile:  path.Join(root, ".ssh/grafana_pdc"),
 	}
 }
 
 func (cfg *Config) RegisterFlags(f *flag.FlagSet) {
-	var deprecatedInt int
-
 	def := DefaultConfig()
 
 	cfg.SSHFlags = []string{}
 	f.StringVar(&cfg.KeyFile, "ssh-key-file", def.KeyFile, "The path to the SSH key file.")
-	f.IntVar(&deprecatedInt, "log-level", def.LogLevel, "[DEPRECATED] Use the log.level flag. The level of log verbosity. The maximum is 3.")
-	// use default log level if invalid
-	if cfg.LogLevel > 3 {
-		cfg.LogLevel = def.LogLevel
-	}
 	f.BoolVar(&cfg.SkipSSHValidation, "skip-ssh-validation", false, "Ignore openssh minimum version constraints.")
 	f.Func("ssh-flag", "Additional flags to be passed to ssh. Can be set more than once.", cfg.addSSHFlag)
 	f.BoolVar(&cfg.ForceKeyFileOverwrite, "force-key-file-overwrite", false, "Force a new ssh key pair to be generated")
@@ -169,7 +162,7 @@ func (s *Client) starting(ctx context.Context) error {
 	retryOpts := retry.Opts{MaxBackoff: 16 * time.Second, InitialBackoff: 1 * time.Second}
 	go retry.Forever(retryOpts, func() error {
 		cmd := exec.CommandContext(ctx, s.SSHCmd, flags...)
-		loggerWriter := newLoggerWriterAdapter(s.logger)
+		loggerWriter := newLoggerWriterAdapter(s.logger, s.cfg.LogLevel)
 		cmd.Stdout = loggerWriter
 		cmd.Stderr = loggerWriter
 		_ = cmd.Run()
@@ -227,11 +220,6 @@ func (s *Client) SSHFlagsFromConfig() ([]string, error) {
 	keyFileArr := strings.Split(s.cfg.KeyFile, "/")
 	keyFileDir := strings.Join(keyFileArr[:len(keyFileArr)-1], "/")
 
-	logLevelFlag := ""
-	if s.cfg.LogLevel > 0 {
-		logLevelFlag = "-" + strings.Repeat("v", s.cfg.LogLevel)
-	}
-
 	gwURL := s.cfg.URL
 	user := fmt.Sprintf("%s@%s", s.cfg.PDC.HostedGrafanaID, gwURL.String())
 
@@ -244,7 +232,7 @@ func (s *Client) SSHFlagsFromConfig() ([]string, error) {
 		"TCPKeepAlive":        "no",
 	}
 
-	nonOptionFlags := []string{} // for backwards compatibility, on -v particularly
+	nonOptionFlags := []string{} // for backwards compatibility
 	for _, f := range s.cfg.SSHFlags {
 		name, value, err := extractOptionFromFlag(f)
 		if err != nil {
@@ -277,12 +265,11 @@ func (s *Client) SSHFlagsFromConfig() ([]string, error) {
 		result = append(result, "-o", fmt.Sprintf("%s=%s", o, sshOptions[o]))
 	}
 
-	if logLevelFlag != "" {
-		result = append(result, logLevelFlag)
-	}
-
 	result = append(result, nonOptionFlags...)
 
+	// Always pass -vvv to ssh to get verbose output, which is needed to create metrics from logs.
+	result = append(result, "-vvv")
+
 	return result, nil
 }
 
@@ -302,11 +289,13 @@ func extractOptionFromFlag(flag string) (string, string, error) {
 // Wraps a logger, implements io.Writer and writes to the logger.
 type loggerWriterAdapter struct {
 	logger log.Logger
+	level  string
 }
 
-func newLoggerWriterAdapter(logger log.Logger) loggerWriterAdapter {
+func newLoggerWriterAdapter(logger log.Logger, level string) loggerWriterAdapter {
 	return loggerWriterAdapter{
 		logger: logger,
+		level:  level,
 	}
 }
 
@@ -322,6 +311,11 @@ func (adapter loggerWriterAdapter) Write(p []byte) (n int, err error) {
 			continue
 		}
 
+		// Do not log debug messages if the log level is not debug.
+		if adapter.level != "debug" && strings.HasPrefix(string(msg), "debug") {
+			continue
+		}
+
 		if err := level.Info(adapter.logger).Log("msg", msg); err != nil {
 			return 0, fmt.Errorf("writing log statement")
 		}

pkg/ssh/ssh_test.go

@@ -146,7 +146,7 @@ func TestClient_SSHArgs(t *testing.T) {
 		result, err := sshClient.SSHFlagsFromConfig()
 
 		assert.Nil(t, err)
-		assert.Equal(t, strings.Split(fmt.Sprintf("-i %s [email protected] -p 22 -R 0 -o CertificateFile=%s -o ConnectTimeout=1 -o ServerAliveInterval=15 -o TCPKeepAlive=no -o UserKnownHostsFile=%s -vv", cfg.KeyFile, cfg.KeyFile+certSuffix, path.Join(cfg.KeyFileDir(), ssh.KnownHostsFile)), " "), result)
+		assert.Equal(t, strings.Split(fmt.Sprintf("-i %s [email protected] -p 22 -R 0 -o CertificateFile=%s -o ConnectTimeout=1 -o ServerAliveInterval=15 -o TCPKeepAlive=no -o UserKnownHostsFile=%s -vvv", cfg.KeyFile, cfg.KeyFile+certSuffix, path.Join(cfg.KeyFileDir(), ssh.KnownHostsFile)), " "), result)
 	})
 
 	t.Run("legacy args (deprecated)", func(t *testing.T) {
@@ -173,7 +173,6 @@ func TestClient_SSHArgs(t *testing.T) {
 		}
 
 		cfg.SSHFlags = []string{
-			"-vvv",
 			"-o TestOption=2",
 			"-o PermitRemoteOpen=host:123 host:456",
 			"-o ConnectTimeout=3",
@@ -198,62 +197,12 @@ func TestClient_SSHArgs(t *testing.T) {
 			"-o", "TCPKeepAlive=no",
 			"-o", "TestOption=2",
 			"-o", fmt.Sprintf("UserKnownHostsFile=%s", path.Join(cfg.KeyFileDir(), ssh.KnownHostsFile)),
-			"-vv",
 			"-vvv",
 		}
 		assert.Equal(t, expected, result)
 
 	})
 
-	t.Run("allow updating the log verbosity", func(t *testing.T) {
-		cfg := ssh.DefaultConfig()
-		cfg.LogLevel = 0
-
-		sshClient := newTestClient(t, cfg, false)
-		result, err := sshClient.SSHFlagsFromConfig()
-
-		assert.Nil(t, err)
-		expected := []string{
-			"-i",
-			cfg.KeyFile,
-			"@localhost",
-			"-p",
-			"22",
-			"-R",
-			"0",
-			"-o", fmt.Sprintf("CertificateFile=%s", cfg.KeyFile+certSuffix),
-			"-o", "ConnectTimeout=1",
-			"-o", "ServerAliveInterval=15",
-			"-o", "TCPKeepAlive=no",
-			"-o", fmt.Sprintf("UserKnownHostsFile=%s", path.Join(cfg.KeyFileDir(), ssh.KnownHostsFile)),
-		}
-		assert.Equal(t, expected, result)
-
-		cfg.LogLevel = 2
-
-		sshClient = newTestClient(t, cfg, false)
-		result, err = sshClient.SSHFlagsFromConfig()
-
-		assert.Nil(t, err)
-		expected = []string{
-			"-i",
-			cfg.KeyFile,
-			"@localhost",
-			"-p",
-			"22",
-			"-R",
-			"0",
-			"-o", fmt.Sprintf("CertificateFile=%s", cfg.KeyFile+certSuffix),
-			"-o", "ConnectTimeout=1",
-			"-o", "ServerAliveInterval=15",
-			"-o", "TCPKeepAlive=no",
-			"-o", fmt.Sprintf("UserKnownHostsFile=%s", path.Join(cfg.KeyFileDir(), ssh.KnownHostsFile)),
-			"-vv",
-		}
-		assert.Equal(t, expected, result)
-
-	})
-
 	t.Run("errors on invalid option flag", func(t *testing.T) {
 		cfg := ssh.DefaultConfig()