Debug logging (#122)

* add debug logging

* add systemctlUnitExists check

* fix test

google-guest-agent.service

@@ -17,7 +17,6 @@ Type=notify
 ExecStart=/usr/bin/google_guest_agent
 OOMScoreAdjust=-999
 Restart=always
-StandardOutput=journal+console
 
 [Install]
 WantedBy=sshd.service

google_guest_agent/addresses.go

@@ -279,13 +279,15 @@ func (a *addressMgr) set() error {
 
 	if config.Section("NetworkInterfaces").Key("setup").MustBool(true) {
 		if runtime.GOOS != "windows" {
+			logger.Debugf("Configure IPv6")
 			if err := configureIPv6(); err != nil {
 				// Continue through IPv6 configuration errors.
 				logger.Errorf("Error configuring IPv6: %v", err)
 			}
 		}
 
 		if runtime.GOOS != "windows" && !interfacesEnabled {
+			logger.Debugf("Enable network interfaces")
 			if err := enableNetworkInterfaces(); err != nil {
 				return err
 			}
@@ -297,6 +299,7 @@ func (a *addressMgr) set() error {
 		return nil
 	}
 
+	logger.Debugf("Add routes for aliases, forwarded IP and target-instance IPs")
 	// Add routes for IP aliases, forwarded and target-instance IPs.
 	for _, ni := range newMetadata.Instance.NetworkInterfaces {
 		iface, err := getInterfaceByMAC(ni.Mac)
@@ -534,6 +537,8 @@ func enableSLESInterfaces(interfaces []string) error {
 	var err error
 	var priority = 10100
 	for _, iface := range interfaces {
+		logger.Debugf("write enabling ifcfg-%s config", iface)
+
 		var ifcfg *os.File
 		ifcfg, err = os.Create("/etc/sysconfig/network/ifcfg-" + iface)
 		if err != nil {
@@ -558,6 +563,7 @@ func enableSLESInterfaces(interfaces []string) error {
 
 // disableNM writes an ifcfg file with DHCP and NetworkManager disabled.
 func disableNM(iface string) error {
+	logger.Debugf("write disabling ifcfg-%s config", iface)
 	filename := "/etc/sysconfig/network-scripts/ifcfg-" + iface
 	ifcfg, err := os.OpenFile(filename, os.O_WRONLY|os.O_CREATE|os.O_EXCL, 0644)
 	if err == nil {

google_guest_agent/instance_setup.go

@@ -105,6 +105,7 @@ func agentInit(ctx context.Context) {
 	} else {
 		// Linux instance setup.
 		defer runCmd(exec.Command("systemd-notify", "--ready"))
+		defer logger.Debugf("notify systemd")
 
 		if config.Section("Snapshots").Key("enabled").MustBool(false) {
 			logger.Infof("Snapshot listener enabled")
@@ -126,6 +127,8 @@ func agentInit(ctx context.Context) {
 		// run once per boot, but it's harmless to run them on every
 		// boot. If this changes, we will hook these to an explicit
 		// on-boot signal.
+
+		logger.Debugf("set IO scheduler config")
 		if err := setIOScheduler(); err != nil {
 			logger.Warningf("Failed to set IO scheduler: %v", err)
 		}
@@ -141,6 +144,7 @@ func agentInit(ctx context.Context) {
 		// network access, this will become an indefinite wait.
 		// TODO: split agentInit into needs-network and no-network functions.
 		for newMetadata == nil {
+			logger.Debugf("populate first time metadata...")
 			newMetadata, _ = getMetadata(ctx, false)
 			time.Sleep(1 * time.Second)
 		}
@@ -282,6 +286,7 @@ func generateBotoConfig() error {
 }
 
 func writeGuestAttributes(key, value string) error {
+	logger.Debugf("write guest attribute %q", key)
 	client := &http.Client{Timeout: defaultTimeout}
 	finalURL := metadataURL + "instance/guest-attributes/" + key
 	req, err := http.NewRequest("PUT", finalURL, strings.NewReader(value))

google_guest_agent/main.go

@@ -26,6 +26,7 @@ import (
 	"os"
 	"os/exec"
 	"runtime"
+	"strings"
 	"sync"
 	"time"
 
@@ -112,9 +113,15 @@ func runUpdate() {
 		wg.Add(1)
 		go func(mgr manager) {
 			defer wg.Done()
-			if mgr.disabled(runtime.GOOS) || (!mgr.timeout() && !mgr.diff()) {
+			if mgr.disabled(runtime.GOOS) {
+				logger.Debugf("manager %#v disabled, skipping", mgr)
 				return
 			}
+			if !mgr.timeout() && !mgr.diff() {
+				logger.Debugf("manager %#v reports no diff", mgr)
+				return
+			}
+			logger.Debugf("running %#v manager", mgr)
 			if err := mgr.set(); err != nil {
 				logger.Errorf("error running %#v manager: %s", mgr, err)
 			}
@@ -126,8 +133,16 @@ func runUpdate() {
 func run(ctx context.Context) {
 	opts := logger.LogOpts{LoggerName: programName}
 	if runtime.GOOS == "windows" {
-		opts.FormatFunction = logFormat
+		opts.FormatFunction = logFormatWindows
 		opts.Writers = []io.Writer{&serialPort{"COM1"}}
+	} else {
+		opts.FormatFunction = logFormat
+		opts.Writers = []io.Writer{os.Stdout}
+		// Local logging is syslog; we will just use stdout in Linux.
+		opts.DisableLocalLogging = true
+	}
+	if os.Getenv("GUEST_AGENT_DEBUG") != "" {
+		opts.Debug = true
 	}
 
 	var err error
@@ -206,7 +221,7 @@ type execResult struct {
 }
 
 func (e execResult) Error() string {
-	return e.err
+	return strings.TrimSuffix(e.err, "\n")
 }
 
 func (e execResult) ExitCode() int {
@@ -230,6 +245,7 @@ func runCmd(cmd *exec.Cmd) error {
 }
 
 func runCmdOutput(cmd *exec.Cmd) *execResult {
+	logger.Debugf("exec: %v", cmd)
 	var stdout, stderr bytes.Buffer
 	cmd.Stdout = &stdout
 	cmd.Stderr = &stderr
@@ -263,11 +279,23 @@ func containsString(s string, ss []string) bool {
 	return false
 }
 
-func logFormat(e logger.LogEntry) string {
+func logFormatWindows(e logger.LogEntry) string {
 	now := time.Now().Format("2006/01/02 15:04:05")
+	// 2006/01/02 15:04:05 GCEGuestAgent This is a log message.
 	return fmt.Sprintf("%s %s: %s", now, programName, e.Message)
 }
 
+func logFormat(e logger.LogEntry) string {
+	switch e.Severity {
+	case logger.Error, logger.Critical, logger.Debug:
+		// ERROR file.go:82 This is a log message.
+		return fmt.Sprintf("%s %s:%d %s", strings.ToUpper(e.Severity.String()), e.Source.File, e.Source.Line, e.Message)
+	default:
+		// This is a log message.
+		return e.Message
+	}
+}
+
 func closer(c io.Closer) {
 	err := c.Close()
 	if err != nil {

google_guest_agent/metadata.go

@@ -236,6 +236,7 @@ func watchMetadata(ctx context.Context) (*metadata, error) {
 }
 
 func getMetadata(ctx context.Context, hang bool) (*metadata, error) {
+	logger.Debugf("getMetadata, %t", hang)
 	client := &http.Client{
 		Timeout: defaultTimeout,
 	}

google_guest_agent/non_windows_accounts.go

@@ -100,12 +100,15 @@ func (a *accountsMgr) disabled(os string) bool {
 
 func (a *accountsMgr) set() error {
 	if sshKeys == nil {
+		logger.Debugf("initialize sshKeys map")
 		sshKeys = make(map[string][]string)
 	}
 
+	logger.Debugf("create sudoers file if needed")
 	if err := createSudoersFile(); err != nil {
 		logger.Errorf("Error creating google-sudoers file: %v.", err)
 	}
+	logger.Debugf("create sudoers group if needed")
 	if err := createSudoersGroup(); err != nil {
 		logger.Errorf("Error creating google-sudoers group: %v.", err)
 	}
@@ -119,21 +122,24 @@ func (a *accountsMgr) set() error {
 	for _, key := range removeExpiredKeys(mdkeys) {
 		idx := strings.Index(key, ":")
 		if idx == -1 {
+			logger.Debugf("invalid ssh key entry: %q", key)
 			continue
 		}
 		user := key[:idx]
 		if user == "" {
+			logger.Debugf("invalid ssh key entry: %q", key)
 			continue
 		}
 		userKeys := mdKeyMap[user]
 		userKeys = append(userKeys, key[idx+1:])
 		mdKeyMap[user] = userKeys
 	}
 
+	logger.Debugf("read google users file")
 	gUsers, err := readGoogleUsersFile()
 	if err != nil {
 		// TODO: is this OK to continue past?
-		logger.Errorf("Couldn't read google users file: %v.", err)
+		logger.Errorf("Couldn't read google_users file: %v.", err)
 	}
 
 	// Update SSH keys, creating Google users as needed.
@@ -175,6 +181,7 @@ func (a *accountsMgr) set() error {
 	}
 
 	// Update the google_users file if we've added or removed any users.
+	logger.Debugf("write google_users file")
 	if err := writeGoogleUsersFile(); err != nil {
 		logger.Errorf("Error writing google_users file: %v.", err)
 	}

google_guest_agent/oslogin.go

@@ -105,27 +105,32 @@ func (o *osloginMgr) set() error {
 
 	for _, svc := range []string{"nscd", "unscd", "systemd-logind", "cron", "crond"} {
 		// These services should be restarted if running
+		logger.Debugf("systemctl try-restart %s, if it exists", svc)
 		if err := systemctlTryRestart(svc); err != nil {
 			logger.Errorf("Error restarting service: %v.", err)
 		}
 	}
 
 	// SSH should be started if not running, reloaded otherwise.
 	for _, svc := range []string{"ssh", "sshd"} {
+		logger.Debugf("systemctl reload-or-restart %s, if it exists", svc)
 		if err := systemctlReloadOrRestart(svc); err != nil {
 			logger.Errorf("Error reloading service: %v.", err)
 		}
 	}
 
 	if enable {
+		logger.Debugf("Create OS Login dirs, if needed")
 		if err := createOSLoginDirs(); err != nil {
 			logger.Errorf("Error creating OS Login directory: %v.", err)
 		}
 
+		logger.Debugf("create OS Login sudoers config, if needed")
 		if err := createOSLoginSudoersFile(); err != nil {
 			logger.Errorf("Error creating OS Login sudoers file: %v.", err)
 		}
 
+		logger.Debugf("starting OS Login nss cache fill")
 		if err := runCmd(exec.Command("google_oslogin_nss_cache")); err != nil {
 			logger.Errorf("Error updating NSS cache: %v.", err)
 		}
@@ -157,6 +162,7 @@ func filterGoogleLines(contents string) []string {
 }
 
 func writeConfigFile(path, contents string) error {
+	logger.Debugf("writing %s", path)
 	file, err := os.OpenFile(path, os.O_WRONLY|os.O_TRUNC, 0777)
 	if err != nil {
 		return err
@@ -351,17 +357,31 @@ func createOSLoginSudoersFile() error {
 // systemctlTryRestart tries to restart a systemd service if it is already
 // running. Stopped services will be ignored.
 func systemctlTryRestart(servicename string) error {
+	if !systemctlUnitExists(servicename) {
+		return nil
+	}
 	return runCmd(exec.Command("systemctl", "try-restart", servicename+".service"))
 }
 
 // systemctlReloadOrRestart tries to reload a running systemd service if
 // supported, restart otherwise. Stopped services will be started.
 func systemctlReloadOrRestart(servicename string) error {
+	if !systemctlUnitExists(servicename) {
+		return nil
+	}
 	return runCmd(exec.Command("systemctl", "reload-or-restart", servicename+".service"))
 }
 
 // systemctlStart tries to start a stopped systemd service. Started services
 // will be ignored.
 func systemctlStart(servicename string) error {
+	if !systemctlUnitExists(servicename) {
+		return nil
+	}
 	return runCmd(exec.Command("systemctl", "start", servicename+".service"))
 }
+
+func systemctlUnitExists(servicename string) bool {
+	res := runCmdOutput(exec.Command("systemctl", "list-units", "--all", servicename+".service"))
+	return !strings.Contains(res.Stdout(), "0 loaded units listed")
+}