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?
before:
_bk;t=1685747370072~~~ group a
_bk;t=1685747370098waiting...
_bk;t=1685747370098~~~ group b
_bk;t=1685747508706message
_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
after:
_bk;t=1685748563941~~~ group a
_bk;t=1685748563967waiting...
_bk;t=1685748563967finished
_bk;t=1685748691209~~~ group b
_bk;t=1685748696258message
_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=1685985670885awaiting
e_bk;t=1685985670885a~~~ group b
e_bk;t=1685985680942amessage
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