wda_wrapper extensive logging leads to crush

[LukaszTutur]

PRECONDITIONS: 1 coordinator is setup properly 2 wda proxy can be accessed on port 8100 correctly STEPS: 1 setup any automated test on the phone through wda FAILURE DESCRIPTION: 1 after few test executions the wda_wrapper starts to use way more cpu than normally 2 the wda on port 8100 is not longer available 3 whatever automated test is crushing (since it can not access port 8100)

WORKAROUND: 1 remove logging from wda_wrapper.go (and rebuild) 2 increase sleep timeouts (probably overcautious)

[LukaszTutur]

package main

import (
    "bufio"
    "encoding/json"
    "flag"
    "fmt"
    "os/exec"
    "strconv"
    "strings"
    "time"

    log "github.com/sirupsen/logrus"
    zmq "github.com/zeromq/goczmq"
)

var exit bool
var reqSock *zmq.Sock
var reqOb *zmq.ReadWriter

func main() {
    exit = false

    var wdaPort = flag.Int("port", 8100, "WDA Port")
    var uuid = flag.String("uuid", "", "IOS Device UUID")
    var iosVersion = flag.String("iosVersion", "", "IOS Version")
    var wdaRoot = flag.String("wdaRoot", "", "WDA Folder Path")
    flag.Parse()

    setup_zmq()
    proc_wdaproxy(*wdaPort, *uuid, *iosVersion, *wdaRoot)
}

func proc_wdaproxy(
    wdaPort int,
    uuid string,
    iosVersion string,
    wdaRoot string) {

    log.WithFields(log.Fields{
        "type":       "proc_start",
        "proc":       "wda_wrapper",
        "wdaPort":    wdaPort,
        "uuid":       uuid,
        "iosVersion": iosVersion,
        "wdaRoot":    wdaRoot,
    }).Info("wda wrapper started")

    backoff := Backoff{}

    for {
        ops := []string{
            "-p", strconv.Itoa(wdaPort),
            "-q", strconv.Itoa(wdaPort),
            "-d",
            "-W", ".",
            "-u", uuid,
            fmt.Sprintf("--iosversion=%s", iosVersion),
        }

        // LT
        // log.WithFields(log.Fields{
        //  "type": "proc_cmdline",
        //  "cmd":  "../wdaproxy",
        //  "args": ops,
        // }).Info("")

        cmd := exec.Command("../wdaproxy", ops...)

        cmd.Dir = wdaRoot

        outputPipe, err1 := cmd.StdoutPipe()
        // LT
        if err1 != nil {
            //     log.WithFields( log.Fields{
            //         "type": "stdout_pipe_err",
            //         "err": err1,
            //     } ).Error("stdout pipe err")
        }
        errPipe, err2 := cmd.StderrPipe()
        // LT
        if err2 != nil {
            //  log.WithFields(log.Fields{
            //      "type": "stderr_pipe_err",
            //      "err":  err2,
            //  }).Error("stderr pipe err")
        }

        backoff.markStart()
        err := cmd.Start()
        if err != nil {
            // LT
            // log.WithFields(log.Fields{
            //  "type":  "proc_err",
            //  "error": err,
            // }).Error("Error starting wdaproxy")
            backoff.markEnd()
            backoff.wait()
            continue
        }

        // send message that it has started
        msgCoord(map[string]string{
            "type": "wdaproxy_started",
            "uuid": uuid,
        })

        go func() {
            scanner := bufio.NewScanner(outputPipe)
            for scanner.Scan() {
                line := scanner.Text()

                if strings.Contains(line, "is implemented in both") {
                }
                //  } else if strings.Contains(line, "Couldn't write value") {
                //  } else if strings.Contains(line, "GET /status ") {
                //  } else if strings.Contains(line, "] Error") {
                //      // LT
                //      // msgCoord(map[string]string{
                //      //  "type": "wda_error",
                //      //  "line": line,
                //      //  "uuid": uuid,
                //      // })
                //  } else {

                //      // LT
                //      // log.WithFields(log.Fields{
                //      //  "type": "proc_stdout",
                //      //  "line": line,
                //      // }).Info("")
                //      // msgCoord(map[string]string{
                //      //  "type": "wda_stdout",
                //      //  "line": line,
                //      //  "uuid": uuid,
                //      // })

                //      // send line to linelog ( through zmq )
                //  }
            }

            // LT
            time.Sleep(time.Millisecond * 200)
        }()
        scanner := bufio.NewScanner(errPipe)
        for scanner.Scan() {
            line := scanner.Text()

            if strings.Contains(line, "[WDA] successfully started") {
                // send message that WDA has started to coordinator

                // LT
                // msgCoord(map[string]string{
                //  "type": "wda_started",
                //  "uuid": uuid,
                // })
            }

            // send line to coordinator
            // LT
            // log.WithFields(log.Fields{
            //  "type": "proc_stderr",
            //  "line": line,
            // }).Error("")
            // LT
            // msgCoord(map[string]string{
            //  "type": "wda_stderr",
            //  "line": line,
            //  "uuid": uuid,
            // })

            // LT
            time.Sleep(time.Millisecond * 200)
        }

        cmd.Wait()

        backoff.markEnd()

        // send message that it has ended

        // LT
        // log.WithFields(log.Fields{
        //  "type": "proc_end",
        // }).Info("Wdaproxy ended")
        // msgCoord(map[string]string{
        //  "type": "wdaproxy_ended",
        //  "uuid": uuid,
        // })

        if exit {
            break
        }

        backoff.wait()
    }

    close_zmq()
}

type Backoff struct {
    fails          int
    start          time.Time
    elapsedSeconds float64
}

func (self *Backoff) markStart() {
    self.start = time.Now()
}

func (self *Backoff) markEnd() float64 {
    elapsed := time.Since(self.start)
    seconds := elapsed.Seconds()
    self.elapsedSeconds = seconds
    return seconds
}

func (self *Backoff) wait() {
    sleeps := []int{0, 0, 2, 5, 10}
    numSleeps := len(sleeps)
    if self.elapsedSeconds < 20 {
        self.fails = self.fails + 1
        index := self.fails
        if index >= numSleeps {
            index = numSleeps - 1
        }
        sleepLen := sleeps[index]
        if sleepLen != 0 {
            time.Sleep(time.Second * time.Duration(sleepLen))
        }
    } else {
        self.fails = 0
    }
}

func setup_zmq() {
    reqSock = zmq.NewSock(zmq.Push)

    spec := "tcp://127.0.0.1:7300"
    reqSock.Connect(spec)

    var err error
    reqOb, err = zmq.NewReadWriter(reqSock)

    // LT
    if err != nil {
        //  log.WithFields(log.Fields{
        //      "type": "zmq_connect_err",
        //      "err":  err,
        //  }).Error("ZMQ Send Error")
    }

    reqOb.SetTimeout(1000)

    zmqRequest([]byte("dummy"))
}

func close_zmq() {
    reqSock.Destroy()
    reqOb.Destroy()
}

func msgCoord(content map[string]string) {
    data, _ := json.Marshal(content)
    zmqRequest(data)
}

func zmqRequest(jsonOut []byte) {
    err := reqSock.SendMessage([][]byte{jsonOut})
    // LT
    if err != nil {
        //  log.WithFields(log.Fields{
        //      "type": "zmq_send_err",
        //      "err":  err,
        //  }).Error("ZMQ Send Error")
    }
}

[nanoscopic]

The golang wda wrapper code is going to be replaced by C code that works byte by byte.

Another option that may be pursued in the future is keeping the Golang code and altering it to read a byte at a time. The code should also be altered not to use Go couroutines. Just like in C, it is possible in Go to check a stream in a nonblocking way: https://medium.com/@cpuguy83/non-blocking-i-o-in-go-bc4651e3ac8d

The current progress of a C rewrite can be seen here: https://github.com/nanoscopic/zmqwrapper/blob/master/wrapper.c

The idea of the C rewrite is to have a generic tool for wrapping subprocesses instead of one specialized to WDA. It should be configuration driven, instead of having any of the messages hardcoded.

The WDA wrapper only exists to begin with in order to begin to make it possible to update the coordinator to newer code without shutting down the WDA. The intent is to make all of the subprocesses work in this way; having all of them be run as LaunchAgents.

[nanoscopic]

Changes have been made to the wda_wrapper that should prevent this from occurring. To ensure this is updated on your setup, do the following:

1. Pull the updated stf_ios_support repo git pull
2. Remove bin/wda_wrapper rm bin/wda_wrapper
3. Rerun make
4. Ensure a new bin/wda_wrapper was built ls bin/wda_wrapper

[nanoscopic]

I believe this issue is resolved. Closing until evidence presents that this is still an issue in some way.