wrong output(ConEmu cmd): time seq 1 10 | tail -2

[smalltalkman]

# time --help
BusyBox v1.37.0-FRP-5301-gda71f7c57 (2024-02-20 13:56:32 GMT)

Usage: time [-pa] [-f FMT] [-o FILE] PROG ARGS

Run PROG, display resource usage when it exits

        -p      POSIX output format
        -f FMT  Custom format
        -o FILE Write result to FILE
        -a      Append (else overwrite)

# time seq 1 10
1
2
3
4
5
6
7
8
9
10
real    0m 0.09s
user    0m 0.01s
sys     0m 0.01s

# time seq 1 10 | tail -2
9
10al
0m 0.15s
user    0m 0.00s
sys     0m 0.01s

[avih]

It's unclear what you consider "wrong output". Can you clarify what you're expecting?

Does the issue happen every time you try? or only sometimes?

Generally, time prints its output to stderr, while tail prints to stdout, and also the outputs are printed from different processes, so these outputs can get intermixed - which is expected and shouldn't be considered an issue.

E.g. in two consecutive runs I get this, and both results are valid:

$ time seq 1 10 | tail -2
real    9
10
0m 0.01s
user    0m 0.01s
sys     0m 0.01s

$ time seq 1 10 | tail -2
9
10
real    0m 0.01s
user    0m 0.00s
sys     0m 0.00s

However, it does look like your output is missing the "re" part of "real" from time - which shouldn't happen - and which I can't reproduce.

Is this the Unicode busybox buld? Does it work better with the non-Unicode busybox? (do try few times). Does it happen (with the Unicode build) if you first run chcp 65001 ?

Trying to analyze the behavior, maybe the "10" from tail is overwriting the same line as "real" from time? If yes, that might be a console/terminal issue.

Which terminal do you use? can you try a different terminal if you have any available?

Regardless, you should know that according to POSIX, using time in any element of a pipe chain is not guaranteed to produce expected results, i.e. the measurement can be "wrong". From POSIX docs of time:

When time is used as part of a pipeline, the times reported are
unspecified, except when it is the sole command within a grouping
command ... in that pipeline. For example, the commands on the left
are unspecified; those on the right report on utilities a and c,
respectively:

time a | b | c    { time a; } | b | c
a | b | time c    a | b | (time c)

[rmyorston]

GNU time is documented to send its output to stderr, and BusyBox time does the same.

[avih]

GNU time is documented to send its output to stderr, and BusyBox time does the same.

That's POSIX:

The time utility shall invoke the utility named by the utility operand with arguments supplied as the argument operands and write a message to standard error ...

And the intermix is more from different processes than stdout/err IMO.

Regardless, the real issue I see at the OP output is that it looks like "10" from tail is overwriting the "real" output sting from time, and I don't get how this can happen except if it's a terminal bug (missing lock at the implementation of WriteConsoleW), or some issue with writeCon_utf8 (less likely, because the outputs should come from different processes, so I don't see how it can get botched).

[avih]

@rmyorston It's not possible that writeCon_utf8 is called concurrently from two threads in the same process, right? becaue this could cause such issues (as the "10"/"real" overwrite).

But as far as I know, there are no threads in busybox, including in pipes and no-fork applets, right?

[rmyorston]

But as far as I know, there are no threads in busybox, including in pipes and no-fork applets, right?

Correct.

[smalltalkman]

It's unclear what you consider "wrong output". Can you clarify what you're expecting?

The desired output should be similar to the following:

# time seq 1 10 | tail -2
9
10

real 0m 0.09s user 0m 0.01s sys 0m 0.01s

> Does the issue happen every time you try? or only sometimes?
> 
So far, I don't see the above command output is the same as gnu linux.
> Generally, `time` prints its output to stderr, while `tail` prints to stdout, and also the outputs are printed from different processes, so these outputs can get intermixed - which is expected and shouldn't be considered an issue.
> 
> E.g. in two consecutive runs I get this, and both results are valid:
> 
> ```shell
> $ time seq 1 10 | tail -2
> real    9
> 10
> 0m 0.01s
> user    0m 0.01s
> sys     0m 0.01s
> 
> $ time seq 1 10 | tail -2
> 9
> 10
> real    0m 0.01s
> user    0m 0.00s
> sys     0m 0.00s
> ```
> 
> However, it does look like your output is missing the "re" part of "real" from `time` - which shouldn't happen - and which I can't reproduce.
> 
Here are the results I just tested:

time seq 1 10 | tail -2

9 real 10 0m 0.14s user 0m 0.00s sys 0m 0.01s

time seq 1 10 | tail -2

9 10 real 0m 0.12s user 0m 0.00s sys 0m 0.01s

> Is this the Unicode busybox buld? Does it work better with the non-Unicode busybox? (do try few times). Does it happen (with the Unicode build) if you first run `chcp 65001` ?
> 
I used the link given by the official website: https://frippery.org/files/busybox/busybox64.exe
> Trying to analyze the behavior, maybe the "10" from `tail` is overwriting the same line as "real" from `time`? If yes, that might be a console/terminal issue.
> 
> Which terminal do you use? can you try a different terminal if you have any available?
> 
I executed `busybox64.exe sh -l` in ConEmu and cmd gave the same result.

[smalltalkman]

This is the test result in msys2:

lenovo@lenovo-PC MSYS /c/Users/lenovo/Desktop
# time seq 1 10 | tail -2
9
10

real    0m0.176s
user    0m0.015s
sys     0m0.030s

The test results are consistent with those under Ubuntu. It seems that the time command under Linux will wait for all subsequent commands to complete before performing output operations.

Aha, put the command into a script and execute time script.sh to get the desired result

[avih]

I used the link given by the official website: https://frippery.org/files/busybox/busybox64.exe

Right. That's the non-Unicode version. (the Unicode version is busybox64u.exe).

The desired output should be similar to the following:

# time seq 1 10 | tail -2
9
10

real    0m 0.09s
user    0m 0.01s
sys     0m 0.01s

Right, so as far as I can tell, the issue you're reporting is that the output from time is intermixed with the output of tail, yes? I.e. you expected first the complete output from tail, followed by the complete output from time?

In this case, as explained above, it's not an issue if they intermix, because they come from two different processes which can print to the terminal concurrently, and how the outputs get merged at the terminal is largely random.

I executed busybox64.exe sh -l in ConEmu

Except for the msys2 test, did you run all your examples in ConEmu?

Because your original report shows something which looks like a terminal bug:

# time seq 1 10 | tail -2
9
10al
0m 0.15s
...

where "10" from tail seem to overwrite the begining of the string "real" from time.

And here there's also an anomaly which I think points to probably the same terminal bug:

# time seq 1 10 | tail -2
9       10
real
...

because it shouldn't be possible to have "9" and "10" at the same line.

If these are indeed copied from ConEmu (are they?), then in the future, please copy the output when you run your example in the normal Windows Console (preferably), or the Windows terminal.

Of course, if you suspect that busybox-w32 behaves incorrectly only in ConEmu, then do test it in ConEmu, and mention that it works OK in the normal windows console, but behaves incorrectly in ConEmu.

[avih]

Just as an example why you can't expect the output from the first pipe element to always get printed after the output from the second pipe element, is when the first pipe element finishes quicker, e.g.:

$ time echo first | (cat; sleep 1; echo last)
first
real    0m 0.01s
user    0m 0.01s
sys     0m 0.00s
last

In this case, cat happens to complete first (printing "first"), then time completes (printing the measurements), and then the 2nd echo completes (printng "last"). So you see that the outputs from the two sides of the pipe get mixed.

How exactly they get mixed depends on the timing of the two pipe sides (in this example, constolled by sleep 1 at the 2nd pipe element), and if the two sides complete roughtly together, then they get mixed in some random order.

[smalltalkman]

The desired output should be similar to the following:

# time seq 1 10 | tail -2
9
10

real    0m 0.09s
user    0m 0.01s
sys     0m 0.01s

Right, so as far as I can tell, the issue you're reporting is that the output from time is intermixed with the output of tail, yes? I.e. you expected first the complete output from tail, followed by the complete output from time?

In this case, as explained above, it's not an issue if they intermix, because they come from two different processes which can print to the terminal concurrently, and how the outputs get merged at the terminal is largely random.

Sorry I didn't describe the problem clearly. In fact, my problem includes the two aspects you pointed out: the output should not overlap, and the time output should be tailed. Now I understand the reason for the latter problem.

I executed busybox64.exe sh -l in ConEmu

Except for the msys2 test, did you run all your examples in ConEmu?

Because your original report shows something which looks like a terminal bug:

# time seq 1 10 | tail -2
9
10al
0m 0.15s
...

where "10" from tail seem to overwrite the begining of the string "real" from time.

And here there's also an anomaly which I think points to probably the same terminal bug:

# time seq 1 10 | tail -2
9       10
real
...

because it shouldn't be possible to have "9" and "10" at the same line.

If these are indeed copied from ConEmu (are they?), then in the future, please copy the output when you run your example in the normal Windows Console (preferably), or the Windows terminal.

Of course, if you suspect that busybox-w32 behaves incorrectly only in ConEmu, then do test it in ConEmu, and mention that it works OK in the normal windows console, but behaves incorrectly in ConEmu.

This is the output under cmd:

D:\gym\softwares\busybox>busybox64.exe sh -l
~ #
~ # time seq 1 10 | tail -2
9
10
real    0m 0.17s
user    0m 0.00s
sys     0m 0.03s
~ #
~ #
~ #
~ #
~ # time seq 1 10 | tail -2
9
10
real    0m 0.22s
user    0m 0.03s
sys     0m 0.00s
~ #
~ #
~ #
~ #
~ # time seq 1 10 | tail -2
real    9
10
0m 0.13s
user    0m 0.00s
sys     0m 0.01s
~ #
~ #
~ # time seq 1 10 | tail -2
9
10
real    0m 0.15s
user    0m 0.00s
sys     0m 0.01s
~ #
~ #

[avih]

This is the output under cmd:

Yes, but is it inside ConEmu? Or inside the normal Windows Console?

[smalltalkman]

This is the output under cmd:

Yes, but is it inside ConEmu? Or inside the normal Windows Console?

In the Win+R dialog box, enter cmd to start

[avih]

In the Win+R dialog box, enter cmd to start

Right. That should be the normal windows console (unless ConEmu installs some hack to make it run in ConEmu instead, but I don't think it would do such thing).

In this case, it's concerning, because it looks to me like some terminal/console issue.

I can't reproduce the overlap issue, and I don't think it's a busybox-w32 bug, but hard to tell really, because I can't reproduce it after dozens of attempts (neither overwrite of anything between the two sides, nor "9" and "10" at the same line).

@rmyorston thoughts?

[smalltalkman]

Currently, putting the command into a script solves the problem I am facing. thank you very much for your help @avih @rmyorston .

[rmyorston]

thoughts?

• I notice that I get mixed output more frequently when my system is heavily loaded. Like when compilations are running.
• GNU time never seems to suffer from this on Linux. It also outputs an empty line before printing the times, to separate the output.

• Making the output buffered seems to help:

  
  diff --git a/miscutils/time.c b/miscutils/time.c
  index e24221341..494122afb 100644
  --- a/miscutils/time.c
  +++ b/miscutils/time.c
  @@ -524,6 +524,11 @@ int time_main(int argc UNUSED_PARAM, char **argv)
  
  /* Cheat. printf's are shorter :) */
  xdup2(output_fd, STDOUT_FILENO);
  +#if ENABLE_PLATFORM_MINGW32

• if (output_fd == STDERR_FILENO)
• setvbuf(stdout, NULL, _IOFBF, 256);

• bb_putchar('\n'); +#endif summarize(output_format, argv, &res);

  ex = WEXITSTATUS(res.waitstatus);

[avih]

Well well well...

After exactly 4 attempts, in ConEmu, I was able to reproduce both instances of the "overwrite issue":

$ path/to/busybox sh -l       

sh ~
$ time seq 1 10 | tail -2          
9       10                         
real                               
0m 0.01s                           
user    0m 0.01s                   
sys     0m 0.01s                   

sh ~
$ time seq 1 10 | tail -2          
real    9                          
10                                 
0m 0.01s                           
user    0m 0.01s                   
sys     0m 0.00s                   

sh ~
$ time seq 1 10 | tail -2          
real    9                          
10                                 
0m 0.01s                           
user    0m 0.01s                   
sys     0m 0.00s                   

sh ~
$ time seq 1 10 | tail -2          
9                                  
10al                               
0m 0.01s                           
user    0m 0.00s                   
sys     0m 0.00s                   

The first output has the "9 and 10 at the same line" issue, and the last output has the "10 overwrites real" issue.

This makes me think that:

1. The overwrite issue is a bug in ConEmu.
2. On @smalltalkman system, running "Win+R and then cmd" somehow makes it run in ConEmu.

In the Win+R dialog box, enter cmd to start

@smalltalkman after you start cmd as described, and BEFORE you start busybox sh -l, can you please try this command, and post the output here?

echo %CONEMUCFGDIR%

I notice that I get mixed output more frequently when my system is heavily loaded. Like when compilations are running.

Right. mixed is expected, and indeed more likely under heavy load, because the output can be slower, and therefore less "atomic", and so more susceptible to get mixed from two processes.

• Making the output line-buffered seems to help:

Right, this should help with not mixing at the same line, but in general I don't think tty output should be line buffered (e.g. I'd imagine the read command, especially with a prompt, might not print the prompt).

However, my question was about the "terminal bug" issue, where some output from one process seem to overwrite some chars from the other process, e.g. in the last example above, the "re" part of "real" from time is not seen anywhere at the output - it seems to be overwritten by "10".

Or, at the 1st example, it should not be possible to have "9" and "10" at the same line, because tail should definitely print a newline between them.

[smalltalkman]

In the Win+R dialog box, enter cmd to start

@smalltalkman after you start cmd as described, and BEFORE you start busybox sh -l, can you please try this command, and post the output here?

echo %CONEMUCFGDIR%

D:\gym\softwares\busybox>
D:\gym\softwares\busybox>
D:\gym\softwares\busybox>
D:\gym\softwares\busybox>
D:\gym\softwares\busybox>echo %CONEMUCFGDIR%
%CONEMUCFGDIR%

D:\gym\softwares\busybox>busybox64.exe sh -l ~ # ~ # ~ # ~ # time seq 1 10 | tail -2 9 10 real 0m 0.17s user 0m 0.01s sys 0m 0.01s ~ # ~ # time seq 1 10 | tail -2 9 10 real 0m 0.13s user 0m 0.00s sys 0m 0.00s ~ # ~ # time seq 1 10 | tail -2 9 10 real 0m 0.20s user 0m 0.00s sys 0m 0.01s ~ # ~ # time seq 1 10 | tail -2 9 10 real 0m 0.13s user 0m 0.00s sys 0m 0.00s ~ # ~ # time seq 1 10 | tail -2 9 10 real 0m 0.15s user 0m 0.00s sys 0m 0.01s ~ # ~ # time seq 1 10 | tail -2 9 10 real 0m 0.13s user 0m 0.00s sys 0m 0.01s ~ #

Seems to be working fine now.

[smalltalkman]

I think disabling buffering would be useful (including for the console).

setbuf(stdout, 0);
setbuf(stderr, 0);

This avoids a lot of weird console behavior.

[avih]

D:\gym\softwares\busybox>echo %CONEMUCFGDIR%
%CONEMUCFGDIR%

Hmm.. I think this means it's not running in ConEmu...

Seems to be working fine now.

So you can't reproduce "9 and 10 at the same line" or "10 overwrites real" anymore?

Did anything change since the previous attempts - which produced these issues more than once?

Any chance these two issues only happened when you tested in ConEmu?

For me, these two issues only happen in ConEmu.

This avoids a lot of weird console behavior.

What kinds of weird behavior are you talking about, other than interleaving outputs from different processes at the same line?

As a developers side note, it would not be trivial to support tty line-buffering with the Unicode build (except when the codepage is 65001, because then we use the libc io functions rather than writeCon_utf8), though I still don't know what's the general practice for tty output - I'm not sure it's line buffered.

C99 says of the default state of the standard streams (7.19.3.7):

... As initially opened, the standard error stream is not fully buffered; the standard input and standard output streams are fully buffered if and only if the stream can be determined not to refer to an interactive device.

When not fully-buffered (i.e. an interactive device, like tty), it doesn't say whether they're unbuffered or line-buffered, but looking around, line-buffered is only mentioned in conjunction with setvbuf, so I think they're unbuffered by default with a tty device.

[smalltalkman]

Seems to be working fine now.

So you can't reproduce "9 and 10 at the same line" or "10 overwrites real" anymore?

My tests in cmd so far have not reproduced either situation. Here are today’s tests:

~ # time seq 1 10 | tail -2
9
10
real    0m 0.12s
user    0m 0.00s
sys     0m 0.01s
~ #
~ #
~ # time seq 1 10 | tail -2
real    9
10
0m 0.18s
user    0m 0.00s
sys     0m 0.01s
~ #
~ #
~ # time seq 1 10 | tail -2
real    0m 0.75s
user    0m 0.01s
sys     0m 0.00s
9
10
~ #
~ #
~ # echo %CONEMUCFGDIR%
%CONEMUCFGDIR%
~ #
~ #

But cmd in ConEmu exists, and new override types appear:

~ # time seq 1 10 | tail -2
9       10
real
0m 0.13s
user    0m 0.00s
sys     0m 0.03s
~ #
~ #
~ # time seq 1 10 | tail -2
9
10      0m 0.14s
user    0m 0.00s
sys     0m 0.03s
~ #
~ #
~ # time seq 1 10 | tail -2
real    9
10
0m 0.14s
user    0m 0.00s
sys     0m 0.03s
~ #
~ # time seq 1 10 | tail -2
9
10al
0m 0.17s
user    0m 0.00s
sys     0m 0.01s
~ #

Did anything change since the previous attempts - which produced these issues more than once?

Any chance these two issues only happened when you tested in ConEmu?

For me, these two issues only happen in ConEmu.

I just executed the test in the cmd environment in win and ConEmu, and no other changes occurred. As you guessed: the problem occurs in ConEmu, and so far no problems mentioned above have been found under win.com.

This avoids a lot of weird console behavior.

What kinds of weird behavior are you talking about, other than interleaving outputs from different processes at the same line?

I encountered many misalignment problems when processing vlang output in msys2, such as the prompt output must be flushed, the parent process output must be flushed before using _wsystem to call the child process, printf has buffering and WriteFile has no buffering, etc. However, I don't remember if there was any coverage issue. As a developers side note, it would not be trivial to support tty line-buffering with the Unicode build (except when the codepage is 65001, because then we use the libc io functions rather than writeCon_utf8), though I still don't know what's the general practice for tty output - I'm not sure it's line buffered.

In my understanding, line buffering does not exist at all in win32 (maybe I'm wrong). _IOLBF For some systems, this mode provides line buffering. However, for Win32, the behavior is the same as _IOFBF - Full Buffering. Ref: windows setvbuf remarks What is the writeCon_utf8 function? I didn't find it on Google. Is it a wrapper for calling WriteConsole? To process tty output under windows, you need to use _isatty detection. However, this is not enough when dealing with pseudo-consoles such as msys2. GetFileInformationByHandleEx is also needed to help detect the pipe file name to confirm whether it is a console. Ref: https://fossies.org/linux/vim/src/iscygpty.c I think for console programs it's worth disabling output buffering (I don't have a deep understanding of busybox-w32, please ignore my mistakes)

[smalltalkman]

So far, I think I have found a solution. Is it necessary to continue the discussion?

Off topic: Does busybox-w32 have a discussion platform like irc? I think it is better to discuss issues on these platforms and summarize them here.

[rmyorston]

My reference to line-buffering above was incorrect. Not least because the code used _IOFBF. I edited the comment to remove it, but not before @avih had pasted it into a reply. Sorry for the confusion.

I've applied a patch to buffer stderr in the time applet. It's not perfect, but it is an improvement. Available in prereleases PRE-5317 and above.

IRC is a fad that passed me by. I don't use it.

[avih]

As you guessed: the problem occurs in ConEmu, and so far no problems mentioned above have been found under win.com.

Good. So we can probably finally put the overwrite issue asside.

I was suspecting it's a terminal issue since my first post, and I think we now largely confirmed it as a ConEmu issue.

I was concerned about it, because as long as we didn't know what caused it, we couldn't rule out a busybox-w32 bug, and if it was a busybox-w32 issue, we'd have wanted to fix it. So I think we're good now.

Feel free to report it to ConEmu.

What kinds of weird behavior are you talking about, other than interleaving outputs from different processes at the same line?

I encountered many misalignment problems when processing vlang output in msys2...

I meant whether you noticed any issues in busybox-w32. If you did, then please post some examples, and we can check if it can be improved.

Do note that this interleaving behavior is limited to console output. If you redirect (or pipe) the output of the relevant stream (stdout or stderr) someplace, then there wouldn't be any issue. It only happens when two processes write concurrently to the console, and so the outputs can get interleaved (but not overwrite eachother) depending on their timing.

What is the writeCon_utf8 function? ... Is it a wrapper for calling WriteConsole?

Yes. It's an internal wrapper of WriteConsoleW, and we use it at the Unicode busybox-w32 as a backend for file IO when the output goes to the console, so that UTF-8 outputs display correctly at the console even if the console output codepage is not UTF-8 (65001).

This comment was mainly an internal note that [line] buffering would not be simple to have while using this function.

To process tty output under windows, you need to use _isatty detection. However, this is not enough when dealing with pseudo-consoles such as msys2.

The console detection and handling in busybox-w32 is fairly good. The console system on windows (including pseudo consoles) is complex, and currently busybox-w32 should work reasonably well also in msys2 pseudo console, but whether it does or doesn't is more of an msys2 concern (specifically, cygwin, which is the base of msys2), rather than busybox-w32.

[avih]

I've applied a patch to buffer stderr in the time applet.

Nice, and weirdly, this seem to work for me also with a Unicode build (i.e. the output from time is no longer interleaved with the output of tail).

But Unicode should not be affacted, because all console output should end up using writeCon_utf8 - which doesn't buffer (except incomplete codepoint UTF8 bytes).

I looked into it a bit, and it turns out that ansi_emulate and ansi_emulate_write use direct libc IO functions if the string doesn't have ESC and is fully ASCII - bypassing writeCon_utf8.

So this is a bug, because if the stream is buffered, then ASCII-only writes are buffered, while non-ASCII writes through writeCon_utf8 are not buffered, which can lead to incorrect output order, e.g. :

$ ./busybox time -f"real-%e   user-%U   sys-%S" true

real-0.00   user-0.00   sys-0.00
$ ./busybox time -f"real-%e   🚀-%U   sys-%S" true
   🚀-
real-0.010.00   sys-0.00
$

(the newline before the output rather than at the end is also part of this issue, because winansi_{putchar,fputc} don't have this ASCII optimization, so they end up unbuffered via writeCon_utf8)

And when bypassing writeCon_utf8 using LC_ALL=C or when the console output CP is UTF8, then the order is correct:

$ LC_ALL=C ./busybox time -f"real-%e   🚀-%U   sys-%S" true
real-0.00   🚀-0.00   sys-0.00

$ chcp 65001
Active code page: 65001

$ ./busybox time -f"real-%e   🚀-%U   sys-%S" true
real-0.01   🚀-0.04   sys-0.01

$

I'll open a PR to handle it, probably by flushing before we call writeCon_utf8 - which is likely to "override" the buffered behavior of time in this case in the unicode build.

We can discuss it at the PR, but feel free to suggest an approach while you're here.

[smalltalkman]

Thanks, my problem is solved.