Log group incorrect timestamp

Hi I noticed some unexpected log group duration rendering behavior. In the ‘before’ case, ‘group a’ renders 0s, and ‘group b’ renders ‘2m 36s’ when the real elapsed time occurs between the ‘waiting…’ line and ‘group b’ line. I was able to work around this issue by adding a ‘finished’ line, but this looks like an error in how the group timestamps are determined. Can this error please be addressed so that me and my teammates can rely on this to identify potential issues in our code?


_bk;t=1685747370072~~~ group a
_bk;t=1685747370098~~~ group b
_bk;t=1685747525700~~~ group c

2023-06-02 16:09:30 PDT	group a         0s
2023-06-02 16:09:30 PDT	waiting...
2023-06-02 16:09:30 PDT	group b     2m 36s
2023-06-02 16:11:48 PDT	message
2023-06-02 16:12:05 PDT	group c      1m 9s


_bk;t=1685748563941~~~ group a
_bk;t=1685748691209~~~ group b
_bk;t=1685748712452~~~ group c

2023-06-02 16:29:23 PDT	group a      2m 7s
2023-06-02 16:29:23 PDT	waiting...
2023-06-02 16:29:23 PDT	finished    
2023-06-02 16:31:31 PDT	group b        21s
2023-06-02 16:31:36 PDT	message
2023-06-02 16:31:52 PDT	group c     2m 21s

here is a minimal example where I was able to reproduce the incorrect behavior

echo "~~~ group a"
echo "waiting"
sleep 10
echo "~~~ group b"
echo "message"
echo "~~~ group c"

and build logs

e_bk;t=1685985670885a~~~ group a
e_bk;t=1685985670885a~~~ group b
e_bk;t=1685985680942a~~~ group c

2023-06-05 10:21:10 PDT	group a   0s
2023-06-05 10:21:10 PDT	waiting
2023-06-05 10:21:10 PDT	group b   10s
2023-06-05 10:21:20 PDT	message
2023-06-05 10:21:20 PDT	group c   0s

Hey @starr!

This is an interesting problem you’re having.

Can you send a link to the build where you’re having this issue to support@buildkite.com so we can take a closer look at this?

Thank you!

Thank you. I sent an email with an example job