Add option to timestamp lines #430
Conversation
| @@ -73,18 +73,16 @@ func (h *HeaderTimesStreamer) Scan(line string) { | |||
| h.scanWaitGroup.Add(1) | |||
| defer h.scanWaitGroup.Done() | |||
|
|
|||
| if h.lineIsHeader(line) { | |||
There was a problem hiding this comment.
I'm probably missing something, but I think this should still be there? Otherwise each line is probably considered a ---header right?
There was a problem hiding this comment.
I had to move that check out of header_times_streamer.go, it introduces some more coupling but I didn't want the check to happen twice. Unfortunately I have to know if something is a header before I can timestamp it, so it's done here now:
https://github.com/buildkite/agent/pull/430/files#diff-14ee62401fee1966227df2f4ab955c3cR192
|
Hey @stefanmb - this is awesome! I'm just doing a code review now and we'll probably need to do some manual testing on our end. But I'm happy to add it to stable once we've done everything we need to! |
agent/job_runner.go
Outdated
| @@ -59,13 +60,20 @@ func (r JobRunner) Create() (runner *JobRunner, err error) { | |||
| // the Buildkite Agent API | |||
| runner.logStreamer = LogStreamer{MaxChunkSizeBytes: r.Job.ChunksMaxSizeBytes, Callback: r.onUploadChunk}.New() | |||
|
|
|||
| timestamp, err := strconv.ParseBool(os.Getenv("BUILDKITE_TIMESTAMP_LINES")) | |||
There was a problem hiding this comment.
Maybe we should check this in AgentConfiguration? Or are you thinking that BUILDKITE_TIMESTAMP_LINES could be turned on/off from the BK UI at runtime?
There was a problem hiding this comment.
Sure, I can move it there!
| // otherwise we let the goroutines take the perf hit. | ||
|
|
||
| checkedForCallback := false | ||
| lineHasCallback := false |
There was a problem hiding this comment.
This bit here has me a little confused. lineHasCallback always seems to be false unless timestamping has been turned on?
There was a problem hiding this comment.
Yeah, that variable is not strictly needed but I left it for clarity.
The idea was to use a short circuit evaluation to prevent doing the check twice in case the timestamping option is enabled: https://github.com/buildkite/agent/pull/430/files#diff-14ee62401fee1966227df2f4ab955c3cR207
I admit it's not super elegant.
agent/job_runner.go
Outdated
| PTY: r.AgentConfiguration.RunInPty, | ||
| Timestamp: timestamp, | ||
| StartCallback: r.onProcessStartCallback, | ||
| LineCallback: runner.headerTimesStreamer.Scan, |
There was a problem hiding this comment.
Ohhh right right, I see how this works now. Took a while for it to click :)
So essentially, LineCallback will only be called if the LineCallbackFilter function returns true for a particular line, is that right?
There was a problem hiding this comment.
That's exactly the idea! The ugly bit of coupling is that lines are not timestamped if there is any callback handler. However, the only callback handler that exists right now is used for the header timestamps.
|
@keithpitt I've moved the env variable to |
|
Rad, I've just done some local testing and it works great. Let's merge it! |
|
I think we forgot to port this to master… |
|
Is this something that can be enabled per-pipeline? Or can it only be set at agent level? |
|
Agent level as I implemented it. |
Background:
The issue in buildkite/feedback#80 has become a showstopper for me. I am supporting a Buildkite based container building service which allows users to provide their own complex build scripts. There are often performance problems that must be diagnosed. Since I do not control the individual build steps I cannot add group header to their build output in order to get timing information. I require an option to timestamp each line of output so we can profile any part of the build.
I've tried ad-hoc solutions involving
tsandunbufferbut they are not drop-in replacements, this feature is needed in the agent itself.Changes:
This PR adds a
BUILDKITE_TIMESTAMP_LINESenvironment variable. If set to one of1, t, T, TRUE, true, True, 0, f, Feach line of output will be prefixed with an RFC3339 UTC timestamp.Note that the header groups are not affected.
I've tried to avoid introducing perf hits (due to single-threaded regex parsing) if the option is not enabled. The code became a bit complex as the header API appears to only transmit a list of timestamps and their matching headers must be parsed a second time by the backend, so they cannot be prefixed. Unfortunately this approach does introduce more coupling between
process.goandheader_times_streamer.go.I made this PR against
2-3-stablebecause that's what we're using. If you want me to port it tomasterplease let me know.Review:
Would greatly appreciate some comments from @keithpitt @toolmantim.
cc: @camilo @n1koo