1// Copyright 2018 Google Inc. All rights reserved.
2//
3// Licensed under the Apache License, Version 2.0 (the "License");
4// you may not use this file except in compliance with the License.
5// You may obtain a copy of the License at
6//
7//     http://www.apache.org/licenses/LICENSE-2.0
8//
9// Unless required by applicable law or agreed to in writing, software
10// distributed under the License is distributed on an "AS IS" BASIS,
11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12// See the License for the specific language governing permissions and
13// limitations under the License.
14
15package status
16
17import (
18	"bufio"
19	"fmt"
20	"io"
21	"os"
22	"regexp"
23	"runtime"
24	"strings"
25	"syscall"
26	"time"
27
28	"google.golang.org/protobuf/proto"
29
30	"android/soong/ui/logger"
31	"android/soong/ui/status/ninja_frontend"
32)
33
34// NewNinjaReader reads the protobuf frontend format from ninja and translates it
35// into calls on the ToolStatus API.
36func NewNinjaReader(ctx logger.Logger, status ToolStatus, fifo string) *NinjaReader {
37	os.Remove(fifo)
38
39	if err := syscall.Mkfifo(fifo, 0666); err != nil {
40		ctx.Fatalf("Failed to mkfifo(%q): %v", fifo, err)
41	}
42
43	n := &NinjaReader{
44		status:     status,
45		fifo:       fifo,
46		forceClose: make(chan bool),
47		done:       make(chan bool),
48		cancelOpen: make(chan bool),
49	}
50
51	go n.run()
52
53	return n
54}
55
56type NinjaReader struct {
57	status     ToolStatus
58	fifo       string
59	forceClose chan bool
60	done       chan bool
61	cancelOpen chan bool
62}
63
64const NINJA_READER_CLOSE_TIMEOUT = 5 * time.Second
65
66// Close waits for NinjaReader to finish reading from the fifo, or 5 seconds.
67func (n *NinjaReader) Close() {
68	// Signal the goroutine to stop if it is blocking opening the fifo.
69	close(n.cancelOpen)
70
71	// Ninja should already have exited or been killed, wait 5 seconds for the FIFO to be closed and any
72	// remaining messages to be processed through the NinjaReader.run goroutine.
73	timeoutCh := time.After(NINJA_READER_CLOSE_TIMEOUT)
74	select {
75	case <-n.done:
76		return
77	case <-timeoutCh:
78		// Channel is not closed yet
79	}
80
81	n.status.Error(fmt.Sprintf("ninja fifo didn't finish after %s", NINJA_READER_CLOSE_TIMEOUT.String()))
82
83	// Force close the reader even if the FIFO didn't close.
84	close(n.forceClose)
85
86	// Wait again for the reader thread to acknowledge the close before giving up and assuming it isn't going
87	// to send anything else.
88	timeoutCh = time.After(NINJA_READER_CLOSE_TIMEOUT)
89	select {
90	case <-n.done:
91		return
92	case <-timeoutCh:
93		// Channel is not closed yet
94	}
95
96	n.status.Verbose(fmt.Sprintf("ninja fifo didn't finish even after force closing after %s", NINJA_READER_CLOSE_TIMEOUT.String()))
97}
98
99func (n *NinjaReader) run() {
100	defer close(n.done)
101
102	// Opening the fifo can block forever if ninja never opens the write end, do it in a goroutine so this
103	// method can exit on cancel.
104	fileCh := make(chan *os.File)
105	go func() {
106		f, err := os.Open(n.fifo)
107		if err != nil {
108			n.status.Error(fmt.Sprintf("Failed to open fifo: %v", err))
109			close(fileCh)
110			return
111		}
112		fileCh <- f
113	}()
114
115	var f *os.File
116
117	select {
118	case f = <-fileCh:
119		// Nothing
120	case <-n.cancelOpen:
121		return
122	}
123
124	defer f.Close()
125
126	r := bufio.NewReader(f)
127
128	running := map[uint32]*Action{}
129
130	msgChan := make(chan *ninja_frontend.Status)
131
132	// Read from the ninja fifo and decode the protobuf in a goroutine so the main NinjaReader.run goroutine
133	// can listen
134	go func() {
135		defer close(msgChan)
136		for {
137			size, err := readVarInt(r)
138			if err != nil {
139				if err != io.EOF {
140					n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err))
141				}
142				return
143			}
144
145			buf := make([]byte, size)
146			_, err = io.ReadFull(r, buf)
147			if err != nil {
148				if err == io.EOF {
149					n.status.Print(fmt.Sprintf("Missing message of size %d from ninja\n", size))
150				} else {
151					n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err))
152				}
153				return
154			}
155
156			msg := &ninja_frontend.Status{}
157			err = proto.Unmarshal(buf, msg)
158			if err != nil {
159				n.status.Print(fmt.Sprintf("Error reading message from ninja: %v", err))
160				continue
161			}
162
163			msgChan <- msg
164		}
165	}()
166
167	for {
168		var msg *ninja_frontend.Status
169		var msgOk bool
170		select {
171		case <-n.forceClose:
172			// Close() has been called, but the reader goroutine didn't get EOF after 5 seconds
173			break
174		case msg, msgOk = <-msgChan:
175			// msg is ready or closed
176		}
177
178		if !msgOk {
179			// msgChan is closed
180			break
181		}
182
183		if msg.BuildStarted != nil {
184			parallelism := uint32(runtime.NumCPU())
185			if msg.BuildStarted.GetParallelism() > 0 {
186				parallelism = msg.BuildStarted.GetParallelism()
187			}
188			// It is estimated from total time / parallelism assumming the build is packing enough.
189			estimatedDurationFromTotal := time.Duration(msg.BuildStarted.GetEstimatedTotalTime()/parallelism) * time.Millisecond
190			// It is estimated from critical path time which is useful for small size build.
191			estimatedDurationFromCriticalPath := time.Duration(msg.BuildStarted.GetCriticalPathTime()) * time.Millisecond
192			// Select the longer one.
193			estimatedDuration := max(estimatedDurationFromTotal, estimatedDurationFromCriticalPath)
194
195			if estimatedDuration > 0 {
196				n.status.SetEstimatedTime(time.Now().Add(estimatedDuration))
197				n.status.Verbose(fmt.Sprintf("parallelism: %d, estimated from total time: %s, critical path time: %s",
198					parallelism,
199					estimatedDurationFromTotal,
200					estimatedDurationFromCriticalPath))
201
202			}
203		}
204		if msg.TotalEdges != nil {
205			n.status.SetTotalActions(int(msg.TotalEdges.GetTotalEdges()))
206		}
207		if msg.EdgeStarted != nil {
208			action := &Action{
209				Description:   msg.EdgeStarted.GetDesc(),
210				Outputs:       msg.EdgeStarted.Outputs,
211				Inputs:        msg.EdgeStarted.Inputs,
212				Command:       msg.EdgeStarted.GetCommand(),
213				ChangedInputs: msg.EdgeStarted.ChangedInputs,
214			}
215			n.status.StartAction(action)
216			running[msg.EdgeStarted.GetId()] = action
217		}
218		if msg.EdgeFinished != nil {
219			if started, ok := running[msg.EdgeFinished.GetId()]; ok {
220				delete(running, msg.EdgeFinished.GetId())
221
222				var err error
223				exitCode := int(msg.EdgeFinished.GetStatus())
224				if exitCode != 0 {
225					err = fmt.Errorf("exited with code: %d", exitCode)
226				}
227
228				outputWithErrorHint := errorHintGenerator.GetOutputWithErrorHint(msg.EdgeFinished.GetOutput(), exitCode)
229				n.status.FinishAction(ActionResult{
230					Action: started,
231					Output: outputWithErrorHint,
232					Error:  err,
233					Stats: ActionResultStats{
234						UserTime:                   msg.EdgeFinished.GetUserTime(),
235						SystemTime:                 msg.EdgeFinished.GetSystemTime(),
236						MaxRssKB:                   msg.EdgeFinished.GetMaxRssKb(),
237						MinorPageFaults:            msg.EdgeFinished.GetMinorPageFaults(),
238						MajorPageFaults:            msg.EdgeFinished.GetMajorPageFaults(),
239						IOInputKB:                  msg.EdgeFinished.GetIoInputKb(),
240						IOOutputKB:                 msg.EdgeFinished.GetIoOutputKb(),
241						VoluntaryContextSwitches:   msg.EdgeFinished.GetVoluntaryContextSwitches(),
242						InvoluntaryContextSwitches: msg.EdgeFinished.GetInvoluntaryContextSwitches(),
243						Tags:                       msg.EdgeFinished.GetTags(),
244					},
245				})
246			}
247		}
248		if msg.Message != nil {
249			message := "ninja: " + msg.Message.GetMessage()
250			switch msg.Message.GetLevel() {
251			case ninja_frontend.Status_Message_INFO:
252				n.status.Status(message)
253			case ninja_frontend.Status_Message_WARNING:
254				n.status.Print("warning: " + message)
255			case ninja_frontend.Status_Message_ERROR:
256				n.status.Error(message)
257			case ninja_frontend.Status_Message_DEBUG:
258				n.status.Verbose(message)
259			default:
260				n.status.Print(message)
261			}
262		}
263		if msg.BuildFinished != nil {
264			n.status.Finish()
265		}
266	}
267}
268
269func readVarInt(r *bufio.Reader) (int, error) {
270	ret := 0
271	shift := uint(0)
272
273	for {
274		b, err := r.ReadByte()
275		if err != nil {
276			return 0, err
277		}
278
279		ret += int(b&0x7f) << (shift * 7)
280		if b&0x80 == 0 {
281			break
282		}
283		shift += 1
284		if shift > 4 {
285			return 0, fmt.Errorf("Expected varint32 length-delimited message")
286		}
287	}
288
289	return ret, nil
290}
291
292// key is pattern in stdout/stderr
293// value is error hint
294var allErrorHints = map[string]string{
295	"Read-only file system": `\nWrite to a read-only file system detected. Possible fixes include
2961. Generate file directly to out/ which is ReadWrite, #recommend solution
2972. BUILD_BROKEN_SRC_DIR_RW_ALLOWLIST := <my/path/1> <my/path/2> #discouraged, subset of source tree will be RW
2983. BUILD_BROKEN_SRC_DIR_IS_WRITABLE := true #highly discouraged, entire source tree will be RW
299`,
300}
301var errorHintGenerator = *newErrorHintGenerator(allErrorHints)
302
303type ErrorHintGenerator struct {
304	allErrorHints                map[string]string
305	allErrorHintPatternsCompiled *regexp.Regexp
306}
307
308func newErrorHintGenerator(allErrorHints map[string]string) *ErrorHintGenerator {
309	var allErrorHintPatterns []string
310	for errorHintPattern, _ := range allErrorHints {
311		allErrorHintPatterns = append(allErrorHintPatterns, errorHintPattern)
312	}
313	allErrorHintPatternsRegex := strings.Join(allErrorHintPatterns[:], "|")
314	re := regexp.MustCompile(allErrorHintPatternsRegex)
315	return &ErrorHintGenerator{
316		allErrorHints:                allErrorHints,
317		allErrorHintPatternsCompiled: re,
318	}
319}
320
321func (errorHintGenerator *ErrorHintGenerator) GetOutputWithErrorHint(rawOutput string, buildExitCode int) string {
322	if buildExitCode == 0 {
323		return rawOutput
324	}
325	errorHint := errorHintGenerator.getErrorHint(rawOutput)
326	if errorHint == nil {
327		return rawOutput
328	}
329	return rawOutput + *errorHint
330}
331
332// Returns the error hint corresponding to the FIRST match in raw output
333func (errorHintGenerator *ErrorHintGenerator) getErrorHint(rawOutput string) *string {
334	firstMatch := errorHintGenerator.allErrorHintPatternsCompiled.FindString(rawOutput)
335	if _, found := errorHintGenerator.allErrorHints[firstMatch]; found {
336		errorHint := errorHintGenerator.allErrorHints[firstMatch]
337		return &errorHint
338	}
339	return nil
340}
341