From b98d3bcf4efd0fa32b4dcd0ef5fc395536760f4d Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Thu, 21 Mar 2019 16:02:58 -0700 Subject: [PATCH 1/2] Wait for ninja proto processing to finish when exiting Wait for the ninja proto processing goroutine to notice the fifo has closed and exit before continuing. Test: m nothing Change-Id: I8cf5f3b8bf6a91496c6d2bbbd3e811eb7f0c9d21 --- ui/build/ninja.go | 3 +- ui/build/soong.go | 3 +- ui/status/Android.bp | 1 + ui/status/ninja.go | 94 ++++++++++++++++++++++++++++++++--------- ui/status/ninja_test.go | 45 ++++++++++++++++++++ 5 files changed, 125 insertions(+), 21 deletions(-) create mode 100644 ui/status/ninja_test.go diff --git a/ui/build/ninja.go b/ui/build/ninja.go index cb41579c5..7994f3a2d 100644 --- a/ui/build/ninja.go +++ b/ui/build/ninja.go @@ -31,7 +31,8 @@ func runNinja(ctx Context, config Config) { defer ctx.EndTrace() fifo := filepath.Join(config.OutDir(), ".ninja_fifo") - status.NinjaReader(ctx, ctx.Status.StartTool(), fifo) + nr := status.NewNinjaReader(ctx, ctx.Status.StartTool(), fifo) + defer nr.Close() executable := config.PrebuiltBuildTool("ninja") args := []string{ diff --git a/ui/build/soong.go b/ui/build/soong.go index c89f0d528..2ce1ac935 100644 --- a/ui/build/soong.go +++ b/ui/build/soong.go @@ -109,7 +109,8 @@ func runSoong(ctx Context, config Config) { defer ctx.EndTrace() fifo := filepath.Join(config.OutDir(), ".ninja_fifo") - status.NinjaReader(ctx, ctx.Status.StartTool(), fifo) + nr := status.NewNinjaReader(ctx, ctx.Status.StartTool(), fifo) + defer nr.Close() cmd := Command(ctx, config, "soong "+name, config.PrebuiltBuildTool("ninja"), diff --git a/ui/status/Android.bp b/ui/status/Android.bp index 76caaef10..901a71309 100644 --- a/ui/status/Android.bp +++ b/ui/status/Android.bp @@ -28,6 +28,7 @@ bootstrap_go_package { ], testSrcs: [ "kati_test.go", + "ninja_test.go", "status_test.go", ], } diff --git a/ui/status/ninja.go b/ui/status/ninja.go index 4ceb5efc5..ee2a2daaa 100644 --- a/ui/status/ninja.go +++ b/ui/status/ninja.go @@ -20,6 +20,7 @@ import ( "io" "os" "syscall" + "time" "github.com/golang/protobuf/proto" @@ -27,9 +28,9 @@ import ( "android/soong/ui/status/ninja_frontend" ) -// NinjaReader reads the protobuf frontend format from ninja and translates it +// NewNinjaReader reads the protobuf frontend format from ninja and translates it // into calls on the ToolStatus API. -func NinjaReader(ctx logger.Logger, status ToolStatus, fifo string) { +func NewNinjaReader(ctx logger.Logger, status ToolStatus, fifo string) *NinjaReader { os.Remove(fifo) err := syscall.Mkfifo(fifo, 0666) @@ -37,14 +38,69 @@ func NinjaReader(ctx logger.Logger, status ToolStatus, fifo string) { ctx.Fatalf("Failed to mkfifo(%q): %v", fifo, err) } - go ninjaReader(status, fifo) + n := &NinjaReader{ + status: status, + fifo: fifo, + done: make(chan bool), + cancel: make(chan bool), + } + + go n.run() + + return n } -func ninjaReader(status ToolStatus, fifo string) { - f, err := os.Open(fifo) - if err != nil { - status.Error(fmt.Sprintf("Failed to open fifo: %v", err)) +type NinjaReader struct { + status ToolStatus + fifo string + done chan bool + cancel 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.cancel) + + timeoutCh := time.After(NINJA_READER_CLOSE_TIMEOUT) + + select { + case <-n.done: + // Nothing + case <-timeoutCh: + n.status.Error(fmt.Sprintf("ninja fifo didn't finish after %s", NINJA_READER_CLOSE_TIMEOUT.String())) } + + return +} + +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.cancel: + return + } + defer f.Close() r := bufio.NewReader(f) @@ -55,7 +111,7 @@ func ninjaReader(status ToolStatus, fifo string) { size, err := readVarInt(r) if err != nil { if err != io.EOF { - status.Error(fmt.Sprintf("Got error reading from ninja: %s", err)) + n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err)) } return } @@ -64,9 +120,9 @@ func ninjaReader(status ToolStatus, fifo string) { _, err = io.ReadFull(r, buf) if err != nil { if err == io.EOF { - status.Print(fmt.Sprintf("Missing message of size %d from ninja\n", size)) + n.status.Print(fmt.Sprintf("Missing message of size %d from ninja\n", size)) } else { - status.Error(fmt.Sprintf("Got error reading from ninja: %s", err)) + n.status.Error(fmt.Sprintf("Got error reading from ninja: %s", err)) } return } @@ -74,13 +130,13 @@ func ninjaReader(status ToolStatus, fifo string) { msg := &ninja_frontend.Status{} err = proto.Unmarshal(buf, msg) if err != nil { - status.Print(fmt.Sprintf("Error reading message from ninja: %v", err)) + n.status.Print(fmt.Sprintf("Error reading message from ninja: %v", err)) continue } // Ignore msg.BuildStarted if msg.TotalEdges != nil { - status.SetTotalActions(int(msg.TotalEdges.GetTotalEdges())) + n.status.SetTotalActions(int(msg.TotalEdges.GetTotalEdges())) } if msg.EdgeStarted != nil { action := &Action{ @@ -88,7 +144,7 @@ func ninjaReader(status ToolStatus, fifo string) { Outputs: msg.EdgeStarted.Outputs, Command: msg.EdgeStarted.GetCommand(), } - status.StartAction(action) + n.status.StartAction(action) running[msg.EdgeStarted.GetId()] = action } if msg.EdgeFinished != nil { @@ -101,7 +157,7 @@ func ninjaReader(status ToolStatus, fifo string) { err = fmt.Errorf("exited with code: %d", exitCode) } - status.FinishAction(ActionResult{ + n.status.FinishAction(ActionResult{ Action: started, Output: msg.EdgeFinished.GetOutput(), Error: err, @@ -112,17 +168,17 @@ func ninjaReader(status ToolStatus, fifo string) { message := "ninja: " + msg.Message.GetMessage() switch msg.Message.GetLevel() { case ninja_frontend.Status_Message_INFO: - status.Status(message) + n.status.Status(message) case ninja_frontend.Status_Message_WARNING: - status.Print("warning: " + message) + n.status.Print("warning: " + message) case ninja_frontend.Status_Message_ERROR: - status.Error(message) + n.status.Error(message) default: - status.Print(message) + n.status.Print(message) } } if msg.BuildFinished != nil { - status.Finish() + n.status.Finish() } } } diff --git a/ui/status/ninja_test.go b/ui/status/ninja_test.go new file mode 100644 index 000000000..c400c97ee --- /dev/null +++ b/ui/status/ninja_test.go @@ -0,0 +1,45 @@ +// Copyright 2019 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 ( + "io/ioutil" + "os" + "path/filepath" + "testing" + "time" + + "android/soong/ui/logger" +) + +// Tests that closing the ninja reader when nothing has opened the other end of the fifo is fast. +func TestNinjaReader_Close(t *testing.T) { + tempDir, err := ioutil.TempDir("", "ninja_test") + if err != nil { + t.Fatal(err) + } + defer os.RemoveAll(tempDir) + + stat := &Status{} + nr := NewNinjaReader(logger.New(ioutil.Discard), stat.StartTool(), filepath.Join(tempDir, "fifo")) + + start := time.Now() + + nr.Close() + + if g, w := time.Since(start), NINJA_READER_CLOSE_TIMEOUT; g >= w { + t.Errorf("nr.Close timed out, %s > %s", g, w) + } +} From 1aeb049a5463c8c87beb8aa034c3899a2f39a893 Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Thu, 21 Mar 2019 16:36:33 -0700 Subject: [PATCH 2/2] Panic if logging is attempted after Close Attempt to catch places where logs are truncated by panicing if logging is attempted after Close. Test: m nothing Change-Id: If670f20d08832ed65b63af5589b548e9815f2f0d --- ui/logger/logger.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/ui/logger/logger.go b/ui/logger/logger.go index 58890e966..9b26ae80a 100644 --- a/ui/logger/logger.go +++ b/ui/logger/logger.go @@ -180,12 +180,16 @@ func (s *stdLogger) SetOutput(path string) *stdLogger { return s } +type panicWriter struct{} + +func (panicWriter) Write([]byte) (int, error) { panic("write to panicWriter") } + // Close disables logging to the file and closes the file handle. func (s *stdLogger) Close() { s.mutex.Lock() defer s.mutex.Unlock() if s.file != nil { - s.fileLogger.SetOutput(ioutil.Discard) + s.fileLogger.SetOutput(panicWriter{}) s.file.Close() s.file = nil }