Step output writer #855

godrei · 2023-02-07T15:22:13Z

Checklist

I've read and followed the Contribution Guidelines
README.md is updated with the changes (if needed)

Version

Context

This PR introduces a new component (stepoutput.Writer), which is responsible for integrating the different writers processing the Step output logs.

Changes

a new stepoutput package

This package was introduced to make the step output writer chain a higher-level code and be able to unit tests the whole writer chain.

errorfinder package

The package was overcomplicated, so it got simplified to make it understandable.

Initially it exposed two structs: errorFinder and defaultErrorFindingWriter. errorFinder was just a tiny layer on top of the defaultErrorFindingWriter, which exposed functionality for creating a new defaultErrorFindingWriter and basically for reading the errors from the underlying defaultErrorFindingWriter.

The new version exposes the ErrorFinder struct, which is primarily an io.Writer, which parses error messages from the output.

Investigation details

Decisions

tothszabi · 2023-02-13T13:45:12Z

stepoutput/stepoutputwriter.go

+func (w Writer) Flush() (int, error) {
+	if w.secretWriter != nil {
+		n, err := w.secretWriter.Flush()
+		if err != nil {
+			return n, err
+		}
+
+	}
+
+	if w.logLevelWriter != nil {
+		return w.logLevelWriter.Flush()
+	}
+
+	return 0, nil
+}


This comment is more of a thinking out loud than an actual comment.

Flush is interesting because as far as I can see (I might be wrong here) the io.Writer does not have a flush mechanism. Based on some stackoverflow answers the writer does write everything remaining when it is closed.

But in our case Flush is called here:

bitrise/tools/tools.go

Line 318 in 04c83d8

if _, ferr := flusher.Flush(); ferr != nil {

When a step execution is done. But we are not reusing our own writers because we create a new one for every step:

bitrise/cli/run_util.go

Line 415 in f7bd078

writer := stepoutput.NewWriter(stepSecrets, opts)

We could reuse the existing io.Closer interface and implement our own closing stuff (which is here in the Flush method) and be a true writer. 😄

Great idea, I updated all the step output writers to implement io.WriteCloser here: da50e4e

tothszabi · 2023-02-13T13:47:06Z

stepoutput/stepoutputwriter.go

@@ -0,0 +1,69 @@
+package stepoutput


This new package was a great idea.

tothszabi · 2023-02-13T14:26:37Z

tools/errorfinder/error_finder.go

-	writers []errorFindingWriter
+// ErrorFinder parses the data coming via the `Write` method and keeps the latest "red" block (that matches \x1b[31;1m control sequence)
+// and hands over tha data to the wrapped `io.Writer` instance.
+type ErrorFinder struct {


This does look better with less abstractions. ⭐

tothszabi · 2023-02-13T14:30:28Z

tools/errorfinder/error_finder.go

+	if e.collecting {
+		if endIndex := getEndColorIndex(haystack); len(endIndex) > 0 {
+			if endIndex[0] != 0 {
+				e.errorMessages = append(e.errorMessages, redRegexp.ReplaceAllString(haystack[0:endIndex[0]], ""))


This is the only bit that has changed compared to the original code block, right?

Yes, I thought it was better to collect all the errors and let the consumer decide which one to use. Also, later we will be able to utilize all the errors.

tothszabi · 2023-02-13T14:44:53Z

tools/tools.go

+	} else {
+		inReader = os.Stdin


This is an interesting catch. Was it a bug or feature? 😄

I have checked all of the codepaths (tried to look up all of them) and it does not seem like we ever wanted to use it. Which does not make this unnecessary but just made me wonder how you caught it?

Just a tiny improvement. When a plugin gets executed with EnvmanRun stdInPayload might be defined, in this case from now on there is -1 assignment.

tothszabi · 2023-02-13T14:50:03Z

tools/tools.go

+	errorParser, isErrorParser := outWriter.(ErrorParser)
+	if err != nil {
+		var exitErr *exec.ExitError
+		if errors.As(err, &exitErr) {
+			exitCode := exitErr.ExitCode()
+
+			if isErrorParser {
+				errorMessages := errorParser.ErrorMessages()
+				if len(errorMessages) > 0 {
+					lastErrorMessage := errorMessages[len(errorMessages)-1]
+					return exitCode, errors.New(lastErrorMessage)
+				}
+			}
+
+			return exitCode, err
+		} else {
+			return 1, fmt.Errorf("executing command failed: %w", err)
 		}
 	}

-	return timeoutcmd.ExitStatus(err), errorFinderWriter.WrapError(err)
+	return 0, nil


These embedded ifs made this block harder to read. I have tried to convert it into a more flat structure and would like to hear you opinion about it:

if err == nil { return 0, nil } var exitErr *exec.ExitError if errors.As(err, &exitErr) == false { return 1, fmt.Errorf("executing command failed: %w", err) } exitCode := exitErr.ExitCode() errorParser, isErrorParser := outWriter.(ErrorParser) if isErrorParser { errorMessages := errorParser.ErrorMessages() if len(errorMessages) > 0 { lastErrorMessage := errorMessages[len(errorMessages)-1] return exitCode, errors.New(lastErrorMessage) } } return exitCode, err

Updated in 8f921fc

tothszabi · 2023-02-13T15:24:25Z

log/logwriter/writer.go

 		logger: logger,
 	}
 }

-func (w LogWriter) Write(p []byte) (n int, err error) {
+// TODO: handle if currentChunk is too big
+func (w *LogLevelWriter) Write(p []byte) (n int, err error) {


This is a meaty function with a lot of cases in it. I wonder if it could simplified in any way.

One idea I have is that if its enough to look for a single colour and its reset code. Our steps log stuff line by line and every line has a closing reset code. In the old implementation we did not care of the embedded colours because those do not contribute to the log level and will be rendered by the website.

I will try to write some rudimentary pseudo code:

func (w *LogLevelWriter) Write(p []byte) (n int, err error) { chunk := string(p) colorCodes := findEmbeddedColors(chunk) if len(colorCodes) > 0 { w.colorStack.add(colorCodes) } resetColorCount := numbeOfResetColors(chunk) currentColor := "" for i := 0; i < resetColorCount; i++ { currentColor = w.colorStack.pop() } w.currentChunk = w.currentChunk + chunk if len(w.colorStack) == 0 { w.logger.LogMessage(w.currentChunk, convertCurrentColorToLevel(currentColor)) w.currentChunk = "" return len(p), nil } return len(p), nil }

I am not yet sure that this logic is correct but what it tries to do is that it collects how many colors are active. Because we are only looking for the outermost one it simply pops the saved colors of the stack as we get the reset codes. Once the stack is empty we log the message based on the last color code the stack had.

This PR took a slightly different direction: the change in this file was the primary functional change to fix the log-level parsing issue.
We decided to do some preliminary work before fixing the original issue.
The remaining file changes are still valid technical improvements, so the function change was reverted and this PR is about technical improvements now.

godrei added 21 commits January 26, 2023 13:09

Move step output writer chain to the stepoutput package

15c5fce

SImplify ErrorFinder

c790766

Merge branch 'master' into log-level

61ca9b8

Test stepoutput.Writer and reproduce the issue

cd0cff6

Update stepoutput.Writer tests

0669e22

Merge branch 'master' into log-level

7cb48da

Update bitrise.yml

7eddf07

Swap errorWriter and secretWriter and add more tests

d68f51d

Merge branch 'master' into log-level

e1d20cc

Implement a new log level writer

d0babb4

Improve EnvmanRun error messages

790c2b6

Cleanup logwriter package

c13e21d

Cleanup

ad35766

Update error_finding_test.go

da130ea

Update tools.go

95e3223

Update filterwriter.go

15b2a18

Code cleanup

50e5480

Code cleanup

04c83d8

Synchronise loglevel writer

f4c0668

Update stepoutputwriter_test.go

f0d46fa

Merge branch 'master' into log-level

f7bd078

tothszabi previously approved these changes Feb 13, 2023

View reviewed changes

Implement io.WriteCloser with the step output writers

da50e4e

godrei dismissed tothszabi’s stale review via da50e4e February 14, 2023 10:04

godrei added 6 commits February 14, 2023 11:07

Merge branch 'master' into log-level

5ae9bc4

Update errorfinder tests

4b96dc1

Improve EnvmanRun error handling

8f921fc

Improve step output writers' synchronisation

94a4ed3

Revert the new LogLevelWriter

10ad3ac

Disable broken test

e088faa

tothszabi approved these changes Feb 17, 2023

View reviewed changes

godrei changed the title ~~Log level~~ Step output writer Feb 21, 2023

godrei marked this pull request as ready for review February 23, 2023 10:24

godrei requested review from morbalint and miklosboros February 23, 2023 10:38

godrei merged commit d997f6c into master Feb 24, 2023

godrei deleted the log-level branch February 24, 2023 10:31

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Step output writer #855

Step output writer #855

godrei commented Feb 7, 2023 •

edited

Loading

tothszabi Feb 13, 2023

godrei Feb 14, 2023

tothszabi Feb 13, 2023

tothszabi Feb 13, 2023

tothszabi Feb 13, 2023

godrei Feb 14, 2023

tothszabi Feb 13, 2023

godrei Feb 14, 2023

tothszabi Feb 13, 2023

godrei Feb 14, 2023

tothszabi Feb 13, 2023

godrei Feb 23, 2023

Step output writer #855

Step output writer #855

Conversation

godrei commented Feb 7, 2023 • edited Loading

Checklist

Version

Context

Changes

Investigation details

Decisions

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

godrei commented Feb 7, 2023 •

edited

Loading