diff --git a/google-guest-agent.service b/google-guest-agent.service index 5057cdeb..0dde23cc 100644 --- a/google-guest-agent.service +++ b/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 diff --git a/google_guest_agent/addresses.go b/google_guest_agent/addresses.go index 0b3a088a..c07c6290 100644 --- a/google_guest_agent/addresses.go +++ b/google_guest_agent/addresses.go @@ -279,6 +279,7 @@ 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) @@ -286,6 +287,7 @@ func (a *addressMgr) set() error { } 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 { diff --git a/google_guest_agent/instance_setup.go b/google_guest_agent/instance_setup.go index 6288c185..da1ead5b 100644 --- a/google_guest_agent/instance_setup.go +++ b/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)) diff --git a/google_guest_agent/main.go b/google_guest_agent/main.go index 21401cfb..3ee1c68a 100644 --- a/google_guest_agent/main.go +++ b/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 { diff --git a/google_guest_agent/metadata.go b/google_guest_agent/metadata.go index c3331838..75bf48cf 100644 --- a/google_guest_agent/metadata.go +++ b/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, } diff --git a/google_guest_agent/non_windows_accounts.go b/google_guest_agent/non_windows_accounts.go index c340e452..dc3688ff 100644 --- a/google_guest_agent/non_windows_accounts.go +++ b/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,10 +122,12 @@ 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] @@ -130,10 +135,11 @@ func (a *accountsMgr) set() error { 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) } diff --git a/google_guest_agent/oslogin.go b/google_guest_agent/oslogin.go index af477466..792bbc59 100644 --- a/google_guest_agent/oslogin.go +++ b/google_guest_agent/oslogin.go @@ -105,6 +105,7 @@ 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) } @@ -112,20 +113,24 @@ func (o *osloginMgr) set() error { // 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") +}