ui/status/ninja.go - platform/build/soong - Git at Google

 // Copyright 2018 Google Inc. All rights reserved.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
 // You may obtain a copy of the License at
 //
 //     http://www.apache.org/licenses/LICENSE-2.0
 //
 // Unless required by applicable law or agreed to in writing, software
 // distributed under the License is distributed on an "AS IS" BASIS,
 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 // See the License for the specific language governing permissions and
 // limitations under the License.

 package status

 import (
 	"bufio"
 	"fmt"
 	"io"
 	"os"
 	"regexp"
 	"runtime"
 	"strings"
 	"syscall"
 	"time"

 	"google.golang.org/protobuf/proto"

 	"android/soong/ui/logger"
 	"android/soong/ui/status/ninja_frontend"
 )

 // NewNinjaReader reads the protobuf frontend format from ninja and translates it
 // into calls on the ToolStatus API.
 func NewNinjaReader(ctx logger.Logger, status ToolStatus, fifo string) *NinjaReader {
 	os.Remove(fifo)

 	if err := syscall.Mkfifo(fifo, 0666); err != nil {
 		ctx.Fatalf("Failed to mkfifo(%q): %v", fifo, err)
 	}

 	n := &NinjaReader{
 		status:     status,
 		fifo:       fifo,
 		forceClose: make(chan bool),
 		done:       make(chan bool),
 		cancelOpen: make(chan bool),
 	}

 	go n.run()

 	return n
 }

 type NinjaReader struct {
 	status     ToolStatus
 	fifo       string
 	forceClose chan bool
 	done       chan bool
 	cancelOpen chan bool
 }

 const NINJA_READER_CLOSE_TIMEOUT = 5 * time.Second

 // Close waits for NinjaReader to finish reading from the fifo, or 5 seconds.
 func (n *NinjaReader) Close() {
 	// Signal the goroutine to stop if it is blocking opening the fifo.
 	close(n.cancelOpen)

 	// Ninja should already have exited or been killed, wait 5 seconds for the FIFO to be closed and any
 	// remaining messages to be processed through the NinjaReader.run goroutine.
 	timeoutCh := time.After(NINJA_READER_CLOSE_TIMEOUT)
 	select {
 	case <-n.done:
 		return
 	case <-timeoutCh:
 		// Channel is not closed yet
 	}

 	n.status.Error(fmt.Sprintf("ninja fifo didn't finish after %s", NINJA_READER_CLOSE_TIMEOUT.String()))

 	// Force close the reader even if the FIFO didn't close.
 	close(n.forceClose)

 	// Wait again for the reader thread to acknowledge the close before giving up and assuming it isn't going
 	// to send anything else.
 	timeoutCh = time.After(NINJA_READER_CLOSE_TIMEOUT)
 	select {
 	case <-n.done:
 		return
 	case <-timeoutCh:
 		// Channel is not closed yet
 	}

 	n.status.Verbose(fmt.Sprintf("ninja fifo didn't finish even after force closing after %s", NINJA_READER_CLOSE_TIMEOUT.String()))
 }

 func (n *NinjaReader) run() {
 	defer close(n.done)

 	// Opening the fifo can block forever if ninja never opens the write end, do it in a goroutine so this
 	// method can exit on cancel.
 	fileCh := make(chan *os.File)
 	go func() {
 		f, err := os.Open(n.fifo)
 		if err != nil {
 			n.status.Error(fmt.Sprintf("Failed to open fifo: %v", err))
 			close(fileCh)
 			return
 		}
 		fileCh <- f
 	}()

 	var f *os.File

 	select {
 	case f = <-fileCh:
 		// Nothing
 	case <-n.cancelOpen:
 		return
 	}

 	defer f.Close()

 	r := bufio.NewReader(f)

 	running := map[uint32]*Action{}

 	msgChan := make(chan *ninja_frontend.Status)

 	// Read from the ninja fifo and decode the protobuf in a goroutine so the main NinjaReader.run goroutine
 	// can listen
 	go func() {
 		defer close(msgChan)
 		for {
 			size, err := readVarInt(r)
 			if err != nil {
 				if err != io.EOF {
 					n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err))
 				}
 				return
 			}

 			buf := make([]byte, size)
 			_, err = io.ReadFull(r, buf)
 			if err != nil {
 				if err == io.EOF {
 					n.status.Print(fmt.Sprintf("Missing message of size %d from ninja\n", size))
 				} else {
 					n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err))
 				}
 				return
 			}

 			msg := &ninja_frontend.Status{}
 			err = proto.Unmarshal(buf, msg)
 			if err != nil {
 				n.status.Print(fmt.Sprintf("Error reading message from ninja: %v", err))
 				continue
 			}

 			msgChan <- msg
 		}
 	}()

 	for {
 		var msg *ninja_frontend.Status
 		var msgOk bool
 		select {
 		case <-n.forceClose:
 			// Close() has been called, but the reader goroutine didn't get EOF after 5 seconds
 			break
 		case msg, msgOk = <-msgChan:
 			// msg is ready or closed
 		}

 		if !msgOk {
 			// msgChan is closed
 			break
 		}

 		if msg.BuildStarted != nil {
 			parallelism := uint32(runtime.NumCPU())
 			if msg.BuildStarted.GetParallelism() > 0 {
 				parallelism = msg.BuildStarted.GetParallelism()
 			}
 			// It is estimated from total time / parallelism assumming the build is packing enough.
 			estimatedDurationFromTotal := time.Duration(msg.BuildStarted.GetEstimatedTotalTime()/parallelism) * time.Millisecond
 			// It is estimated from critical path time which is useful for small size build.
 			estimatedDurationFromCriticalPath := time.Duration(msg.BuildStarted.GetCriticalPathTime()) * time.Millisecond
 			// Select the longer one.
 			estimatedDuration := max(estimatedDurationFromTotal, estimatedDurationFromCriticalPath)

 			if estimatedDuration > 0 {
 				n.status.SetEstimatedTime(time.Now().Add(estimatedDuration))
 				n.status.Verbose(fmt.Sprintf("parallelism: %d, estimated from total time: %s, critical path time: %s",
 					parallelism,
 					estimatedDurationFromTotal,
 					estimatedDurationFromCriticalPath))

 			}
 		}
 		if msg.TotalEdges != nil {
 			n.status.SetTotalActions(int(msg.TotalEdges.GetTotalEdges()))
 		}
 		if msg.EdgeStarted != nil {
 			action := &Action{
 				Description: msg.EdgeStarted.GetDesc(),
 				Outputs:     msg.EdgeStarted.Outputs,
 				Inputs:      msg.EdgeStarted.Inputs,
 				Command:     msg.EdgeStarted.GetCommand(),
 			}
 			n.status.StartAction(action)
 			running[msg.EdgeStarted.GetId()] = action
 		}
 		if msg.EdgeFinished != nil {
 			if started, ok := running[msg.EdgeFinished.GetId()]; ok {
 				delete(running, msg.EdgeFinished.GetId())

 				var err error
 				exitCode := int(msg.EdgeFinished.GetStatus())
 				if exitCode != 0 {
 					err = fmt.Errorf("exited with code: %d", exitCode)
 				}

 				outputWithErrorHint := errorHintGenerator.GetOutputWithErrorHint(msg.EdgeFinished.GetOutput(), exitCode)
 				n.status.FinishAction(ActionResult{
 					Action: started,
 					Output: outputWithErrorHint,
 					Error:  err,
 					Stats: ActionResultStats{
 						UserTime:                   msg.EdgeFinished.GetUserTime(),
 						SystemTime:                 msg.EdgeFinished.GetSystemTime(),
 						MaxRssKB:                   msg.EdgeFinished.GetMaxRssKb(),
 						MinorPageFaults:            msg.EdgeFinished.GetMinorPageFaults(),
 						MajorPageFaults:            msg.EdgeFinished.GetMajorPageFaults(),
 						IOInputKB:                  msg.EdgeFinished.GetIoInputKb(),
 						IOOutputKB:                 msg.EdgeFinished.GetIoOutputKb(),
 						VoluntaryContextSwitches:   msg.EdgeFinished.GetVoluntaryContextSwitches(),
 						InvoluntaryContextSwitches: msg.EdgeFinished.GetInvoluntaryContextSwitches(),
 						Tags:                       msg.EdgeFinished.GetTags(),
 					},
 				})
 			}
 		}
 		if msg.Message != nil {
 			message := "ninja: " + msg.Message.GetMessage()
 			switch msg.Message.GetLevel() {
 			case ninja_frontend.Status_Message_INFO:
 				n.status.Status(message)
 			case ninja_frontend.Status_Message_WARNING:
 				n.status.Print("warning: " + message)
 			case ninja_frontend.Status_Message_ERROR:
 				n.status.Error(message)
 			case ninja_frontend.Status_Message_DEBUG:
 				n.status.Verbose(message)
 			default:
 				n.status.Print(message)
 			}
 		}
 		if msg.BuildFinished != nil {
 			n.status.Finish()
 		}
 	}
 }

 func readVarInt(r *bufio.Reader) (int, error) {
 	ret := 0
 	shift := uint(0)

 	for {
 		b, err := r.ReadByte()
 		if err != nil {
 			return 0, err
 		}

 		ret += int(b&0x7f) << (shift * 7)
 		if b&0x80 == 0 {
 			break
 		}
 		shift += 1
 		if shift > 4 {
 			return 0, fmt.Errorf("Expected varint32 length-delimited message")
 		}
 	}

 	return ret, nil
 }

 // key is pattern in stdout/stderr
 // value is error hint
 var allErrorHints = map[string]string{
 	"Read-only file system": `\nWrite to a read-only file system detected. Possible fixes include
 1. Generate file directly to out/ which is ReadWrite, #recommend solution
 2. BUILD_BROKEN_SRC_DIR_RW_ALLOWLIST := <my/path/1> <my/path/2> #discouraged, subset of source tree will be RW
 3. BUILD_BROKEN_SRC_DIR_IS_WRITABLE := true #highly discouraged, entire source tree will be RW
 `,
 }
 var errorHintGenerator = *newErrorHintGenerator(allErrorHints)

 type ErrorHintGenerator struct {
 	allErrorHints                map[string]string
 	allErrorHintPatternsCompiled *regexp.Regexp
 }

 func newErrorHintGenerator(allErrorHints map[string]string) *ErrorHintGenerator {
 	var allErrorHintPatterns []string
 	for errorHintPattern, _ := range allErrorHints {
 		allErrorHintPatterns = append(allErrorHintPatterns, errorHintPattern)
 	}
 	allErrorHintPatternsRegex := strings.Join(allErrorHintPatterns[:], "|")
 	re := regexp.MustCompile(allErrorHintPatternsRegex)
 	return &ErrorHintGenerator{
 		allErrorHints:                allErrorHints,
 		allErrorHintPatternsCompiled: re,
 	}
 }

 func (errorHintGenerator *ErrorHintGenerator) GetOutputWithErrorHint(rawOutput string, buildExitCode int) string {
 	if buildExitCode == 0 {
 		return rawOutput
 	}
 	errorHint := errorHintGenerator.getErrorHint(rawOutput)
 	if errorHint == nil {
 		return rawOutput
 	}
 	return rawOutput + *errorHint
 }

 // Returns the error hint corresponding to the FIRST match in raw output
 func (errorHintGenerator *ErrorHintGenerator) getErrorHint(rawOutput string) *string {
 	firstMatch := errorHintGenerator.allErrorHintPatternsCompiled.FindString(rawOutput)
 	if _, found := errorHintGenerator.allErrorHints[firstMatch]; found {
 		errorHint := errorHintGenerator.allErrorHints[firstMatch]
 		return &errorHint
 	}
 	return nil
 }
	// Copyright 2018 Google Inc. All rights reserved.
	//
	// Licensed under the Apache License, Version 2.0 (the "License");
	// you may not use this file except in compliance with the License.
	// You may obtain a copy of the License at
	//
	// http://www.apache.org/licenses/LICENSE-2.0
	//
	// Unless required by applicable law or agreed to in writing, software
	// distributed under the License is distributed on an "AS IS" BASIS,
	// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
	// See the License for the specific language governing permissions and
	// limitations under the License.

	package status

	import (
	"bufio"
	"fmt"
	"io"
	"os"
	"regexp"
	"runtime"
	"strings"
	"syscall"
	"time"

	"google.golang.org/protobuf/proto"

	"android/soong/ui/logger"
	"android/soong/ui/status/ninja_frontend"
	)

	// NewNinjaReader reads the protobuf frontend format from ninja and translates it
	// into calls on the ToolStatus API.
	func NewNinjaReader(ctx logger.Logger, status ToolStatus, fifo string) *NinjaReader {
	os.Remove(fifo)

	if err := syscall.Mkfifo(fifo, 0666); err != nil {
	ctx.Fatalf("Failed to mkfifo(%q): %v", fifo, err)
	}

	n := &NinjaReader{
	status: status,
	fifo: fifo,
	forceClose: make(chan bool),
	done: make(chan bool),
	cancelOpen: make(chan bool),
	}

	go n.run()

	return n
	}

	type NinjaReader struct {
	status ToolStatus
	fifo string
	forceClose chan bool
	done chan bool
	cancelOpen chan bool
	}

	const NINJA_READER_CLOSE_TIMEOUT = 5 * time.Second

	// Close waits for NinjaReader to finish reading from the fifo, or 5 seconds.
	func (n *NinjaReader) Close() {
	// Signal the goroutine to stop if it is blocking opening the fifo.
	close(n.cancelOpen)

	// Ninja should already have exited or been killed, wait 5 seconds for the FIFO to be closed and any
	// remaining messages to be processed through the NinjaReader.run goroutine.
	timeoutCh := time.After(NINJA_READER_CLOSE_TIMEOUT)
	select {
	case <-n.done:
	return
	case <-timeoutCh:
	// Channel is not closed yet
	}

	n.status.Error(fmt.Sprintf("ninja fifo didn't finish after %s", NINJA_READER_CLOSE_TIMEOUT.String()))

	// Force close the reader even if the FIFO didn't close.
	close(n.forceClose)

	// Wait again for the reader thread to acknowledge the close before giving up and assuming it isn't going
	// to send anything else.
	timeoutCh = time.After(NINJA_READER_CLOSE_TIMEOUT)
	select {
	case <-n.done:
	return
	case <-timeoutCh:
	// Channel is not closed yet
	}

	n.status.Verbose(fmt.Sprintf("ninja fifo didn't finish even after force closing after %s", NINJA_READER_CLOSE_TIMEOUT.String()))
	}

	func (n *NinjaReader) run() {
	defer close(n.done)

	// Opening the fifo can block forever if ninja never opens the write end, do it in a goroutine so this
	// method can exit on cancel.
	fileCh := make(chan *os.File)
	go func() {
	f, err := os.Open(n.fifo)
	if err != nil {
	n.status.Error(fmt.Sprintf("Failed to open fifo: %v", err))
	close(fileCh)
	return
	}
	fileCh <- f
	}()

	var f *os.File

	select {
	case f = <-fileCh:
	// Nothing
	case <-n.cancelOpen:
	return
	}

	defer f.Close()

	r := bufio.NewReader(f)

	running := map[uint32]*Action{}

	msgChan := make(chan *ninja_frontend.Status)

	// Read from the ninja fifo and decode the protobuf in a goroutine so the main NinjaReader.run goroutine
	// can listen
	go func() {
	defer close(msgChan)
	for {
	size, err := readVarInt(r)
	if err != nil {
	if err != io.EOF {
	n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err))
	}
	return
	}

	buf := make([]byte, size)
	_, err = io.ReadFull(r, buf)
	if err != nil {
	if err == io.EOF {
	n.status.Print(fmt.Sprintf("Missing message of size %d from ninja\n", size))
	} else {
	n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err))
	}
	return
	}

	msg := &ninja_frontend.Status{}
	err = proto.Unmarshal(buf, msg)
	if err != nil {
	n.status.Print(fmt.Sprintf("Error reading message from ninja: %v", err))
	continue
	}

	msgChan <- msg
	}
	}()

	for {
	var msg *ninja_frontend.Status
	var msgOk bool
	select {
	case <-n.forceClose:
	// Close() has been called, but the reader goroutine didn't get EOF after 5 seconds
	break
	case msg, msgOk = <-msgChan:
	// msg is ready or closed
	}

	if !msgOk {
	// msgChan is closed
	break
	}

	if msg.BuildStarted != nil {
	parallelism := uint32(runtime.NumCPU())
	if msg.BuildStarted.GetParallelism() > 0 {
	parallelism = msg.BuildStarted.GetParallelism()
	}
	// It is estimated from total time / parallelism assumming the build is packing enough.
	estimatedDurationFromTotal := time.Duration(msg.BuildStarted.GetEstimatedTotalTime()/parallelism) * time.Millisecond
	// It is estimated from critical path time which is useful for small size build.
	estimatedDurationFromCriticalPath := time.Duration(msg.BuildStarted.GetCriticalPathTime()) * time.Millisecond
	// Select the longer one.
	estimatedDuration := max(estimatedDurationFromTotal, estimatedDurationFromCriticalPath)

	if estimatedDuration > 0 {
	n.status.SetEstimatedTime(time.Now().Add(estimatedDuration))
	n.status.Verbose(fmt.Sprintf("parallelism: %d, estimated from total time: %s, critical path time: %s",
	parallelism,
	estimatedDurationFromTotal,
	estimatedDurationFromCriticalPath))

	}
	}
	if msg.TotalEdges != nil {
	n.status.SetTotalActions(int(msg.TotalEdges.GetTotalEdges()))
	}
	if msg.EdgeStarted != nil {
	action := &Action{
	Description: msg.EdgeStarted.GetDesc(),
	Outputs: msg.EdgeStarted.Outputs,
	Inputs: msg.EdgeStarted.Inputs,
	Command: msg.EdgeStarted.GetCommand(),
	}
	n.status.StartAction(action)
	running[msg.EdgeStarted.GetId()] = action
	}
	if msg.EdgeFinished != nil {
	if started, ok := running[msg.EdgeFinished.GetId()]; ok {
	delete(running, msg.EdgeFinished.GetId())

	var err error
	exitCode := int(msg.EdgeFinished.GetStatus())
	if exitCode != 0 {
	err = fmt.Errorf("exited with code: %d", exitCode)
	}

	outputWithErrorHint := errorHintGenerator.GetOutputWithErrorHint(msg.EdgeFinished.GetOutput(), exitCode)
	n.status.FinishAction(ActionResult{
	Action: started,
	Output: outputWithErrorHint,
	Error: err,
	Stats: ActionResultStats{
	UserTime: msg.EdgeFinished.GetUserTime(),
	SystemTime: msg.EdgeFinished.GetSystemTime(),
	MaxRssKB: msg.EdgeFinished.GetMaxRssKb(),
	MinorPageFaults: msg.EdgeFinished.GetMinorPageFaults(),
	MajorPageFaults: msg.EdgeFinished.GetMajorPageFaults(),
	IOInputKB: msg.EdgeFinished.GetIoInputKb(),
	IOOutputKB: msg.EdgeFinished.GetIoOutputKb(),
	VoluntaryContextSwitches: msg.EdgeFinished.GetVoluntaryContextSwitches(),
	InvoluntaryContextSwitches: msg.EdgeFinished.GetInvoluntaryContextSwitches(),
	Tags: msg.EdgeFinished.GetTags(),
	},
	})
	}
	}
	if msg.Message != nil {
	message := "ninja: " + msg.Message.GetMessage()
	switch msg.Message.GetLevel() {
	case ninja_frontend.Status_Message_INFO:
	n.status.Status(message)
	case ninja_frontend.Status_Message_WARNING:
	n.status.Print("warning: " + message)
	case ninja_frontend.Status_Message_ERROR:
	n.status.Error(message)
	case ninja_frontend.Status_Message_DEBUG:
	n.status.Verbose(message)
	default:
	n.status.Print(message)
	}
	}
	if msg.BuildFinished != nil {
	n.status.Finish()
	}
	}
	}

	func readVarInt(r *bufio.Reader) (int, error) {
	ret := 0
	shift := uint(0)

	for {
	b, err := r.ReadByte()
	if err != nil {
	return 0, err
	}

	ret += int(b&0x7f) << (shift * 7)
	if b&0x80 == 0 {
	break
	}
	shift += 1
	if shift > 4 {
	return 0, fmt.Errorf("Expected varint32 length-delimited message")
	}
	}

	return ret, nil
	}

	// key is pattern in stdout/stderr
	// value is error hint
	var allErrorHints = map[string]string{
	"Read-only file system": `\nWrite to a read-only file system detected. Possible fixes include
	1. Generate file directly to out/ which is ReadWrite, #recommend solution
	2. BUILD_BROKEN_SRC_DIR_RW_ALLOWLIST := <my/path/1> <my/path/2> #discouraged, subset of source tree will be RW
	3. BUILD_BROKEN_SRC_DIR_IS_WRITABLE := true #highly discouraged, entire source tree will be RW
	`,
	}
	var errorHintGenerator = *newErrorHintGenerator(allErrorHints)

	type ErrorHintGenerator struct {
	allErrorHints map[string]string
	allErrorHintPatternsCompiled *regexp.Regexp
	}

	func newErrorHintGenerator(allErrorHints map[string]string) *ErrorHintGenerator {
	var allErrorHintPatterns []string
	for errorHintPattern, _ := range allErrorHints {
	allErrorHintPatterns = append(allErrorHintPatterns, errorHintPattern)
	}
	allErrorHintPatternsRegex := strings.Join(allErrorHintPatterns[:], "\|")
	re := regexp.MustCompile(allErrorHintPatternsRegex)
	return &ErrorHintGenerator{
	allErrorHints: allErrorHints,
	allErrorHintPatternsCompiled: re,
	}
	}

	func (errorHintGenerator *ErrorHintGenerator) GetOutputWithErrorHint(rawOutput string, buildExitCode int) string {
	if buildExitCode == 0 {
	return rawOutput
	}
	errorHint := errorHintGenerator.getErrorHint(rawOutput)
	if errorHint == nil {
	return rawOutput
	}
	return rawOutput + *errorHint
	}

	// Returns the error hint corresponding to the FIRST match in raw output
	func (errorHintGenerator ErrorHintGenerator) getErrorHint(rawOutput string) string {
	firstMatch := errorHintGenerator.allErrorHintPatternsCompiled.FindString(rawOutput)
	if _, found := errorHintGenerator.allErrorHints[firstMatch]; found {
	errorHint := errorHintGenerator.allErrorHints[firstMatch]
	return &errorHint
	}
	return nil
	}