Change daemonize logic in watchdog and add timeout to file system read.

go/src/infra/tools/device_watchdog/main.go

 // Copyright 2016 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 // +build android
 
 // Watchdog daemon for android devices. It will attempt to reboot the device
 // if its uptime exceeds a specified maximum.
 package main
 
 /*
 #cgo LDFLAGS: -landroid -llog
 
 #include <android/log.h>
 #include <string.h>
 */
 import "C"
 
 import (
         "flag"
         "fmt"
         "io/ioutil"
         "os"
+        "os/exec"
         "strconv"
         "strings"
-        "syscall"
         "time"
         "unsafe"
 
         "github.com/luci/luci-go/common/runtime/paniccatcher"
 )
 
 var (
         logHeader = C.CString("CIT_DeviceWatchdog")
 )
 
 type logLevel int
 
 const (
         logInfo = iota
         logWarning
         logError
 )
 
-const (
-        stdInFd  = 0
-        stdOutFd = 1
-        stdErrFd = 2
-)
-
 func (l logLevel) getLogLevel() C.int {
         switch l {
         case logInfo:
                 return C.ANDROID_LOG_INFO
         case logWarning:
                 return C.ANDROID_LOG_WARN
         case logError:
                 return C.ANDROID_LOG_ERROR
         default:
                 panic("Unknown log level.")
         }
 }
 
 func logcatLog(level logLevel, format string, args ...interface{}) {
         cmsg := C.CString(fmt.Sprintf(format, args...))
         defer C.free(unsafe.Pointer(cmsg))
         C.__android_log_write(level.getLogLevel(), logHeader, cmsg)
 }
 
-// Spawn a child process via fork, create new process group, chdir and
-// redirect std in and out to /dev/null.
-func daemonize() (int, error) {
-        ret, _, errno := syscall.Syscall(syscall.SYS_FORK, 0, 0, 0)
-        pid := int(ret)
-        if errno != 0 {
-                return 0, errno
-        }
-        if pid > 0 {
-                return pid, nil
-        }
-
-        _, err := syscall.Setsid()
+// Spawn a child process via exec.
+func daemonize(maxUptime int) (int, error) {

[dnj, 2016/09/02 16:17:32]

This isn't a full daemonize workflow. It doesn't setsid() or (in this case)
handle file descriptor duplication.

This is the sort of thing you need to do:
https://github.com/sevlyar/go-daemon/blob/master/daemon_posix.go#L108

You were already sort of doing it before, but maybe review that for any
improvements (the SysProcAttr struct is interesting).

[bpastene, 2016/09/02 23:02:13]

There were problems with threads not correctly getting scheduled. I kept all the
forking logic and just threw an exec at the end. That fixes it.

+        binary, err := os.Readlink("/proc/self/exe")
         if err != nil {
                 return 0, err
         }
-
-        f, err := os.Open("/dev/null")
+        cmd := exec.Command(binary, "--max-uptime", strconv.Itoa(maxUptime), "--skip-daemonize")
+        err = cmd.Start()
         if err != nil {
                 return 0, err
         }
-        fd := f.Fd()
-        syscall.Dup2(int(fd), stdInFd)
-        syscall.Dup2(int(fd), stdOutFd)
-        syscall.Dup2(int(fd), stdErrFd)
+        return cmd.Process.Pid, nil
+}
 
-        return pid, nil
+type uptimeResult struct {
+        Uptime time.Duration
+        Err    error
 }
 
 // Read from /proc/uptime. Expected format:
 // "uptime_in_seconds cpu_idle_time_in_seconds"
-func getDeviceUptime() (time.Duration, error) {
+// Return the uptime via a channel for use with timeouts.
+func getDeviceUptime(c chan uptimeResult) {

[dnj, 2016/09/02 16:17:32]

Make this a directional channel:
c chan<- uptimeResult

[bpastene, 2016/09/02 23:02:13]

Done.

         bytes, err := ioutil.ReadFile("/proc/uptime")
         if err != nil {
-                return 0, fmt.Errorf("unable to open /proc/uptime: %s", err.Error())
+                c <- uptimeResult{Uptime: 0, Err: fmt.Errorf("unable to open /proc/uptime: %s", err.Error())}
+                return
         }
         // Split on the space to get uptime and drop cpu idle time.
         uptimeFields := strings.Fields(string(bytes))
         if len(uptimeFields) == 0 {
-                return 0, fmt.Errorf("unable to parse /proc/uptime")
+                c <- uptimeResult{Uptime: 0, Err: fmt.Errorf("unable to parse /proc/uptime")}
+                return
         }
         uptime, err := strconv.ParseFloat(uptimeFields[0], 64)
         if err != nil {
-                return 0, fmt.Errorf("unable to parse uptime: %s", err.Error())
+                c <- uptimeResult{Uptime: 0, Err: fmt.Errorf("unable to parse uptime: %s", err.Error())}
+                return
         }
-        return time.Duration(uptime * float64(time.Second)), nil
+        c <- uptimeResult{Uptime: time.Duration(uptime * float64(time.Second)), Err: nil}
 }
 
 // Reboot device by writing to sysrq-trigger. See:
 // https://www.kernel.org/doc/Documentation/sysrq.txt
 func rebootDevice() error {
         fd, err := os.OpenFile("/proc/sysrq-trigger", os.O_WRONLY, 0)
         if err != nil {
                 return fmt.Errorf("Can't open /proc/sysrq-trigger: %s", err.Error())
         }
         defer fd.Close()
         _, err = fd.Write([]byte("b"))
         if err != nil {
                 return fmt.Errorf("Can't reboot: %s", err.Error())
         }
         return fmt.Errorf("I just rebooted. How am I still alive?!?\n")
 }
 
 func realMain() int {
         maxUptimeFlag := flag.Int("max-uptime", 120, "Maximum uptime in minutes before a reboot is triggered.")
+        skipDaemonizeFlag := flag.Bool("skip-daemonize", false, "Skips the daemonize logic. Otherwise it will spawn a copy daemon and exit.")
         flag.Parse()
 
-        os.Chdir("/")
-        pid, err := daemonize()
-        if err != nil {
-                logcatLog(logError, "Failed to daemonize: %s", err.Error())
-                return 1
-        }
-        if pid > 0 {
+        if !*skipDaemonizeFlag {
+                pid, err := daemonize(*maxUptimeFlag)
+                if err != nil {
+                        logcatLog(logError, "Failed to daemonize: %s", err.Error())
+                        return 1
+                }
                 logcatLog(logInfo, "Child spawned with pid %d, exiting parent\n", pid)
                 return 0
         }
 
+        var uptimeRes uptimeResult
         maxUptime := time.Duration(*maxUptimeFlag) * time.Minute
+        consecutiveTimeouts := 0
+        maxTimeouts := 5
         for {
-                uptime, err := getDeviceUptime()
-                if err != nil {
-                        logcatLog(logError, "Failed to get uptime: %s", err.Error())
+                c := make(chan uptimeResult, 1)
+                go getDeviceUptime(c)

[bpastene, 2016/09/02 00:05:22]

Uses a go routine + select statement to add a timeout to getUptime. Let me know
if there's a more clean/go-friendly way of handling timeouts.

[dnj, 2016/09/02 16:17:32]

Select is correct, but you launch a new goroutine each time and don't make a
point of reaping the previous goroutines, which could lead to accumulating
goroutines if they are lagging behind. I think you need to close that loop for
sure. You should also make sure to close the channels when you know you're done
with them if you can.

The timeout is more complicated. You want to limit the number of goroutines that
you spawn, but turn a synchronous operation into an asynchronous one. Along
these lines, I think the thing to do is to have a "get the uptime" function that
runs in a goroutine and loops, receiving "get uptime" requests and returning
responses. This will limit your goroutine to one, and also let you test if
you're blocking.

First, create the monitor. Pass it an RPC request channel. The channel will,
itself, receive response channels. Each time a response channel is received,
that's a new RPC request, and it will get the uptime and push the result onto
the response channel.

type uptimeRPCChannel chan<- chan<- uptimeResponse

func uptimeGetter(reqC uptimeRPCChannel) {
}

// Now, let's wrap that in a "get uptime or timeout" function. We'll add some
additional logic to handle blocking gracefully. We'll mark a timeout using a
special error code.
// Wholly encapsulating the evils of the monitor and timeout in a synchronous
function makes the rest of the program more readable, testable, and
maintainable.
var errTimeout = errors.New("timeout!")

func getUptime(reqC uptimeRPCChannel, timeout time.Duration) (time.Duration,
error) (
  // Create a response channel. Buffer it so that if we timeout, the goroutine
doesn't choke/block.
  respC := make(chan uptimeRespnse, 1)

  // Start our timeout timer.
  timer := time.NewTimer(timeout)
  defer timer.Stop()

  // Try and send the RPC request. This could fail if the RPC goroutine is
blocked.
  select {
  case reqC <- respC:
    break
  case <-timer.C:
    return 0, errTimeout
  }

  // Read the RPC response. This could fail if the request causes the RPC
goroutine to
  // block.
  select {
  case resp <- respC:
    return resp.uptime, resp.err
  case <-timer.C:
    return 0, errTimeout
  }
}

// Now, you can actually use this stuff.
func main() {
  // ...

  // Start the uptime RPC goroutine.
  reqC := make(uptimeRPCChannel)
  go func() {
    for req := range reqC {
      uptime, err := getUptimeFromFile()
      req <- uptimeResponse{uptime, err}
    }
  }()
  defer close(reqC) // Probably not necessary, but cleanup and exit conditions
are good behavior.

  // Main loop.
  for {
    // ...
    uptime, err := getUptime(reqC, 5*time.Second)
    switch err {
    case nil:
      // Valid uptime, yay.
    case errTimeout:
      // Got a timeout.
    default:
      // Some other error.
    }
}

If you want to get fancy, you can start using
https://github.com/luci/luci-go/tree/master/common/clock

This will let you actually simulate the clock in a test, which is awesome
because you can actually test this logic and assert its correctness.

[bpastene, 2016/09/02 23:02:13]

Thanks for the suggestion Dan. I added the single "uptimeGetter" go routine like
you outlined that just responds to RPCs via channels. That should prevent
multiple go routines from getting created if they fail/timeout.

+                select {
+                case uptimeRes = <-c:
+                        consecutiveTimeouts = 0
+                case <-time.After(5 * time.Second):
+                        consecutiveTimeouts++
+                }
+                if consecutiveTimeouts == maxTimeouts {
+                        logcatLog(logError, "%d consective timeouts when fetching uptime. Triggering reboot", maxTimeouts)
+                        break
+                } else if consecutiveTimeouts > 0 {
+                        logcatLog(logError, "Timeout when fetching uptime. Sleeping for 60s and trying again.")
+                        time.Sleep(60 * time.Second)
+                        continue
+                }
+                if uptimeRes.Err != nil {
+                        logcatLog(logError, "Failed to get uptime: %s", uptimeRes.Err.Error())
                         return 1
                 }
 
-                if uptime > maxUptime {
-                        logcatLog(logInfo, "Max uptime exceeded: (%s > %s)\n", uptime, maxUptime)
+                if uptimeRes.Uptime > maxUptime {
+                        logcatLog(logInfo, "Max uptime exceeded: (%s > %s)\n", uptimeRes.Uptime, maxUptime)
                         break
                 }
-                logcatLog(logInfo, "No need to reboot, uptime < max_uptime: (%s < %s)\n", uptime, maxUptime)
-                time.Sleep(maxUptime - uptime + time.Second)
+                logcatLog(logInfo, "No need to reboot, uptime < max_uptime: (%s < %s)\n", uptimeRes.Uptime, maxUptime)
+                time.Sleep(maxUptime - uptimeRes.Uptime + time.Second)

[dnj, 2016/09/02 16:17:32]

(Before the world forgets, add a comment about why you add a second here).

[bpastene, 2016/09/02 23:02:13]

Done.

         }
-        if err = rebootDevice(); err != nil {
+        if err := rebootDevice(); err != nil {
                 logcatLog(logError, "Failed to reboot device: %s", err.Error())
                 return 1
         }
         return 0
 }
 
 func main() {
         paniccatcher.Do(func() {
                 os.Exit(realMain())
         }, func(p *paniccatcher.Panic) {
                 logcatLog(logError, "Panic: %s\n%s", p.Reason, p.Stack)
                 os.Exit(1)
         })
 }