fix: add log for the result of the step

[s-yoshika]

Context

We’d like to analyze the build results and execution times for each step to understand which steps fail most often and which take the longest.

Objective

Add logging for each build step to include:

• step name
• exit code
• execution time

References

License

I confirm that this contribution is made under the terms of the license found in the root directory of this repository's source tree and that I have the authority necessary to make this contribution on behalf of its copyright owner.

[yuichi10]

I think we should also add logging around the doRunSetupCommand function.
Since the logic is almost the same across these parts, maybe we can create a wrapper function to handle the timing and logging.

[foxtrot0304]

I think it would be better if we could also get the setup time.
As for the code logic, using a wrapper tends to make it more complex, so I think it's fine to keep it simple like now.

[s-yoshika]

I think we should also add logging around the doRunSetupCommand function.
Since the logic is almost the same across these parts, maybe we can create a wrapper function to handle the timing and logging.

@yuichi10 For doRunSetupCommand, I think logging is not necessary since this step usually completes very quickly and rarely fails( and I want to avoid repeating the same logging logic any more).

As for the code logic, using a wrapper tends to make it more complex, so I think it's fine to keep it simple like now.

@foxtrot0304 Thanks for your comment, I had the same thought.

[s-yoshika]

The other setup steps are already covered by the current code.

Here are the results from running it locally.

2025/10/10 06:42:17 Completed step: name=sd-setup-launcher, exit_code=0, elapsed_ms=0
2025/10/10 06:42:25 Completed step: name=sd-setup-scm, exit_code=0, elapsed_ms=3700
2025/10/10 06:42:29 Completed step: name=sd-setup-screwdriver-cache-bookend, exit_code=0, elapsed_ms=0
2025/10/10 06:42:34 Completed step: name=step1, exit_code=0, elapsed_ms=1174
2025/10/10 06:42:38 Completed step: name=step2, exit_code=1, elapsed_ms=7
2025/10/10 06:47:42 Completed step: name=teardown-step3, exit_code=0, elapsed_ms=300002
2025/10/10 06:47:54 Completed step: name=sd-teardown-screwdriver-artifact-bookend, exit_code=0, elapsed_ms=8050
2025/10/10 06:47:58 Completed step: name=sd-teardown-screwdriver-coverage-bookend, exit_code=0, elapsed_ms=1
2025/10/10 06:48:02 Completed step: name=sd-teardown-screwdriver-cache-bookend, exit_code=0, elapsed_ms=1

[yuichi10]

The other setup steps are already covered by the current code.

Thank you! You’re right. it looks like logging for doRunSetupCommand isn’t necessary.

As for the code logic, using a wrapper tends to make it more complex, so I think it's fine to keep it simple like now.

I see. I thought it wouldn't be too complex, especially since we don't need to consider doRunSetupCommand.

I just thought we need to prepare one function like below. ( I do not care about func name. Also it's may not work )

func RunWithLogging(name string, fn func() (int, error)) (int, error) {
	start := time.Now()
	code, err := fn()
	elapsedMS := time.Since(start).Milliseconds()
        log.Printf("Completed step: name=%s, exit_code=%d, elapsed_ms=%d", name, code, elapsedMS)
	return code, err
}

runCode, rcErr := RunWithLogging(cmd.Name, func() (int, error) {
	return doRunCommand(guid, stepFilePath, emitter, f, fReader, cmd.Name)
})
eCode <- runCode
runErr <- rcErr

If we're logging the same information in both doRunCommand and doRunTeardownCommand, I felt it would be better to reduce duplicate code. Otherwise, if we need to change the log format later, we'd have to update it in two places.

If the concern is more about having a wrapper itself making things complicated rather than the code being complex, I’m okay with keeping it as is.

[s-yoshika]

@yuichi10 Thanks for the comment — you’re right that if we change the log format later, we’d need to update it in multiple places.
My main concern was that introducing a wrapper just for these logging logic would make the main logic slightly more complex.
With the additional layer, we’d have to be aware of what’s happening inside RunWithLogging when working on this code in the future.

That said, if you think maintainability of the logging format is more important, I’m fine with updating it based on your suggested approach.

[yuichi10]

We only have two places for now, so I think it’s fine to keep it simple without a wrapper.
If we end up having more places doing the same thing, we can wrap it at that point.

[foxtrot0304]

lgtm