Add additional log checkpoint information

cmd/launcher/launcher.go

@@ -104,7 +104,8 @@ func runLauncher(ctx context.Context, cancel func(), opts *launcher.Options) err
 	internal.RecordLauncherVersion(rootDirectory)
 
 	// Try to ensure useful info in the logs
-	checkpoint.Run(logger, db, *opts)
+	checkpointer := checkpoint.New(logger, db, *opts)
+	checkpointer.Run()
 
 	// create the certificate pool
 	var rootPool *x509.CertPool
@@ -178,6 +179,12 @@ func runLauncher(ctx context.Context, cancel func(), opts *launcher.Options) err
 		"build", versionInfo.Revision,
 	)
 
+	go func() {
+		// Sleep to give osquery time to startup before the checkpointer starts using it.
+		time.Sleep(30 * time.Second)
+		checkpointer.SetQuerier(extension)
+	}()
+
 	// Create the control service and services that depend on it
 	var runner *desktopRunner.DesktopUsersProcessesRunner
 	if opts.ControlServerURL == "" {

pkg/log/checkpoint/checkpoint.go

@@ -1,13 +1,16 @@
 package checkpoint
 
 import (
+	"crypto/x509"
+	"encoding/base64"
 	"fmt"
 	"net"
 	"net/http"
 	"net/url"
 	"os"
 	"runtime"
 	"strings"
+	"sync"
 	"time"
 
 	"github.com/go-kit/kit/log"
@@ -40,84 +43,117 @@ type logger interface {
 	Log(keyvals ...interface{}) error
 }
 
-// Run starts a log checkpoint routine. The purpose of this is to
-// ensure we get good debugging information in the logs.
-func Run(logger logger, db *bbolt.DB, opts launcher.Options) {
+type querierInt interface {
+	Query(query string) ([]map[string]string, error)
+}
 
-	// Things to add:
-	//  * invoke osquery for better hardware info
-	//  * runtime stats, like memory allocations
+type checkPointer struct {
+	logger  logger
+	querier querierInt
+	db      *bbolt.DB
+	opts    launcher.Options
 
+	lock        sync.RWMutex
+	queriedInfo map[string]any
+}
+
+func New(logger logger, db *bbolt.DB, opts launcher.Options) *checkPointer {
+	return &checkPointer{
+		logger: log.With(logger, "component", "log checkpoint"),
+		db:     db,
+		opts:   opts,
+
+		lock:        sync.RWMutex{},
+		queriedInfo: make(map[string]any),
+	}
+}
+
+// SetQuerier adds the querier into the checkpointer. It is done in a function, so it can happen
+// later in the startup sequencing.
+func (c *checkPointer) SetQuerier(querier querierInt) {
+	c.querier = querier
+	c.queryStaticInfo()
+	c.logQueriedInfo()
+}
+
+// Run starts a log checkpoint routine. The purpose of this is to
+// ensure we get good debugging information in the logs.
+func (c *checkPointer) Run() {
 	go func() {
-		logCheckPoint(logger, db, opts)
+		c.logCheckPoint()
 
 		for range time.Tick(time.Minute * 60) {
-			logCheckPoint(logger, db, opts)
+			c.logCheckPoint()
 		}
 	}()
 }
 
-func logCheckPoint(logger log.Logger, db *bbolt.DB, opts launcher.Options) {
-	logger = log.With(logger, "msg", "log checkpoint")
-
-	logger.Log("hostname", hostName())
-	logger.Log("runtime", runtimeInfo)
-	logger.Log("launcher", launcherInfo)
-	logger.Log("notableFiles", fileNamesInDirs(notableFileDirs...))
-	logDbSize(logger, db)
-	logConnections(logger, opts)
-	logIpLookups(logger, opts)
-	logKolideServerVersion(logger, opts)
-	logNotaryVersions(logger, opts)
+func (c *checkPointer) logCheckPoint() {
+	// populate and log the queried static info
+	c.queryStaticInfo()
+	c.logQueriedInfo()
+
+	c.logger.Log("runtime", runtimeInfo)
+	c.logger.Log("launcher", launcherInfo)
+	c.logger.Log("hostname", hostName())
+	c.logger.Log("notableFiles", filesInDirs(notableFileDirs...))
+	c.logger.Log("keyinfo", agentKeyInfo())
+	c.logOsqueryInfo()
+	c.logDbSize()
+	c.logKolideServerVersion()
+	c.logConnections()
+	c.logIpLookups()
+	c.logNotaryVersions()
+	c.logServerProvidedData()
 }
 
-func logDbSize(logger log.Logger, db *bbolt.DB) {
-	boltStats, err := agent.GetStats(db)
+func (c *checkPointer) logDbSize() {
+	boltStats, err := agent.GetStats(c.db)
 	if err != nil {
-		logger.Log("bbolt db size", err.Error())
+		c.logger.Log("bbolt db size", err.Error())
 	} else {
-		logger.Log("bbolt db size", boltStats.DB.Size)
+		c.logger.Log("bbolt db size", boltStats.DB.Size)
 	}
 }
 
-func logKolideServerVersion(logger logger, opts launcher.Options) {
-	if !opts.KolideHosted {
+func (c *checkPointer) logKolideServerVersion() {
+	if !c.opts.KolideHosted {
 		return
 	}
 
 	httpClient := &http.Client{Timeout: requestTimeout}
 
-	kolideServerUrl, err := parseUrl(fmt.Sprintf("%s/version", opts.KolideServerURL), opts)
+	kolideServerUrl, err := parseUrl(fmt.Sprintf("%s/version", c.opts.KolideServerURL), c.opts)
 	if err != nil {
-		logger.Log("kolide server version fetch", err)
+		c.logger.Log("kolide server version fetch", err)
 	} else {
-		logger.Log("kolide server version fetch", fetchFromUrls(httpClient, kolideServerUrl))
+		c.logger.Log("kolide server version fetch", fetchFromUrls(httpClient, kolideServerUrl))
 	}
 }
 
-func logNotaryVersions(logger logger, opts launcher.Options) {
-	if !opts.KolideHosted || !opts.Autoupdate {
+func (c *checkPointer) logNotaryVersions() {
+	if !c.opts.KolideHosted || !c.opts.Autoupdate {
 		return
 	}
 
 	httpClient := &http.Client{Timeout: requestTimeout}
 
-	notaryUrl, err := parseUrl(fmt.Sprintf("%s/v2/kolide/launcher/_trust/tuf/targets/releases.json", opts.NotaryServerURL), opts)
+	notaryUrl, err := parseUrl(fmt.Sprintf("%s/v2/kolide/launcher/_trust/tuf/targets/releases.json", c.opts.NotaryServerURL), c.opts)
 	if err != nil {
-		logger.Log("notary versions", err)
+		c.logger.Log("notary versions", err)
 	} else {
-		logger.Log("notary versions", fetchNotaryVersions(httpClient, notaryUrl))
+		c.logger.Log("notary versions", fetchNotaryVersions(httpClient, notaryUrl))
 	}
 }
 
-func logConnections(logger logger, opts launcher.Options) {
+func (c *checkPointer) logConnections() {
 	dialer := &net.Dialer{Timeout: requestTimeout}
-	logger.Log("connections", testConnections(dialer, urlsToTest(opts)...))
+	c.logger.Log("connections", testConnections(dialer, urlsToTest(c.opts)...))
 }
 
-func logIpLookups(logger logger, opts launcher.Options) {
+func (c *checkPointer) logIpLookups() {
 	ipLookuper := &net.Resolver{}
-	logger.Log("ip loook ups", lookupHostsIpv4s(ipLookuper, urlsToTest(opts)...))
+	c.logger.Log("ip look ups", lookupHostsIpv4s(ipLookuper, urlsToTest(c.opts)...))
 }
 
 func urlsToTest(opts launcher.Options) []*url.URL {
@@ -182,3 +218,33 @@ func hostName() string {
 
 	return hostname
 }
+
+func agentKeyInfo() map[string]string {
+	keyinfo := make(map[string]string, 3)
+
+	pub := agent.LocalDbKeys().Public()
+	if pub == nil {
+		keyinfo["local_key"] = "nil. Likely startup delay"
+		return keyinfo
+	}
+
+	if localKeyDer, err := x509.MarshalPKIXPublicKey(pub); err == nil {
+		// der is a binary format, so convert to b64
+		keyinfo["local_key"] = base64.StdEncoding.EncodeToString(localKeyDer)
+	} else {
+		keyinfo["local_key"] = fmt.Sprintf("error marshalling local key (startup is sometimes weird): %s", err)
+	}
+
+	// We don't always have hardware keys. Move on if we don't
+	if agent.HardwareKeys().Public() == nil {
+		return keyinfo
+	}
+
+	if hardwareKeyDer, err := x509.MarshalPKIXPublicKey(agent.HardwareKeys().Public()); err == nil {
+		// der is a binary format, so convert to b64
+		keyinfo["hardware_key"] = base64.StdEncoding.EncodeToString(hardwareKeyDer)
+		keyinfo["hardware_key_source"] = agent.HardwareKeys().Type()
+	}
+
+	return keyinfo
+}

pkg/log/checkpoint/files.go

@@ -1,40 +1,35 @@
 package checkpoint
 
 import (
+	"errors"
 	"fmt"
 	"os"
-	"path/filepath"
+	"strings"
 )
 
-func fileNamesInDirs(dirnames ...string) []string {
-	results := []string{}
-
-	isFilesFound := false
+func filesInDirs(dirnames ...string) map[string]string {
+	results := make(map[string]string)
 
 	for _, dirname := range dirnames {
 		files, err := os.ReadDir(dirname)
 
 		switch {
+		case errors.Is(err, os.ErrNotExist):
+			results[dirname] = "not present"
 		case err != nil:
-			results = append(results, err.Error())
+			results[dirname] = err.Error()
 		case len(files) == 0:
-			results = append(results, emptyDirMsg(dirname))
+			results[dirname] = "present, but empty"
 		default:
-			isFilesFound = true
-			for _, file := range files {
-				results = append(results, filepath.Join(dirname, file.Name()))
+			fileToLog := make([]string, len(files))
+
+			for i, file := range files {
+				fileToLog[i] = file.Name()
 			}
-		}
-	}
 
-	if !isFilesFound {
-		return []string{"No extra osquery files detected"}
+			results[dirname] = fmt.Sprintf("contains: %s", strings.Join(fileToLog, ", "))
+		}
 	}
 
 	return results
 }
-
-// emptyDirMsg is a helper method to generate empty dir message, makes testing easier
-func emptyDirMsg(dirname string) string {
-	return fmt.Sprintf("%s is an empty directory", dirname)
-}